diff --git a/docs/http-api.md b/docs/http-api.md index 2e183ab0..3aef37c5 100644 --- a/docs/http-api.md +++ b/docs/http-api.md @@ -58,7 +58,7 @@ Stops the engine. Returns the current metrics: - Token usage counters (from the engine's Prometheus `/metrics` endpoint) - Host system metrics (GPU, CPU, RAM). On macOS a GPU carries utilisation and name only; its `memoryUsed`, `memoryTotal` and `temperature` are `0`, meaning the host reports none -- `speed`, the engine's own generation rate in tokens per second, parsed from the timing lines it prints into its captured output (llama.cpp's `print_timing` `tg` figure today). Present only while the engine runs and has printed a figure within the last sampler interval — a stopped or quiet engine omits it rather than reporting zero, and so does an engine that prints no rate +- `speed`, the engine's own generation rate in tokens per second, parsed from the timing lines it prints into its captured output (llama.cpp's `print_timing` figure today — its three-second `tg_3s` rate where the line carries a usable one, its whole-task `tg` average otherwise). Present only while the engine runs and has printed a figure within the last sampler interval — a stopped or quiet engine omits it rather than reporting zero, and so does an engine that prints no rate - `history`, the daemon's retained system readings — one per sampler tick while an engine ran, each a 0–100% figure per series (`t` time, `c` CPU, `m` memory, `g` per-GPU utilisation and memory) plus an optional `s` speed point for a tick whose interval saw the engine print a generation rate, covering at most the last 10 minutes - `lastActiveAt` and `idleSeconds`, the same pair `/v1/status` reports diff --git a/docs/maintainer/internals.md b/docs/maintainer/internals.md index f89f7fe3..6eef2681 100644 --- a/docs/maintainer/internals.md +++ b/docs/maintainer/internals.md @@ -49,7 +49,7 @@ These are mistakes already made here; each was silent rather than loud, which is **A captured engine's stdout is a pseudo-terminal, and the normaliser above it is a line model, not a screen emulator.** llama.cpp's download bar prints nothing when its stdout is not a terminal, and the download happens in-process before the HTTP listener comes up — there is no status API to scrape — so the capture (the daemon and the serve view) presents the engine's stdout as a PTY: the only way the progress reaches the engine log at all. `ptylog.go` turns the terminal stream into the log's lines as a column, and three of its rules are easy to break by "simplifying". The engine's up-down cursor dance is *part of each redraw* — the bar's state is drawn between a cursor-up and a cursor-back-down, the cursor parked on an anchor line — so a cursor move must move the drawing between the column's lines and never end a line: committing on a move records every state as a "final" one and resets the dedup, which is how the first design put the whole download, state for state, in the log. A state's replacement is lazy — a carriage return settles the state drawn before it, and the line's content is cleared only by the next text byte — so `S\r\r\n`, the PTY's ONLCR turning a lone `\n` into a CRLF, commits `S` intact. And the tick at the interval's half-rate runs on *every* line of the column, because a bar's last state outlives the engine's move off its line: the download finishes, the engine goes quiet on stdout, and the log still owes it. Because the engine's stdout is now a terminal, the capture branch sets `NO_COLOR=1` in the engine's environment: llama.cpp routes its log lines to stderr and colours them by whether it sees a terminal — *stdout* among them — and the normaliser never sees the stderr path, so without it escapes would reach the log file. The bar draws no colour, so nothing is lost; the forwarding paths (piped `serve`, off-terminal `serve --api`) set nothing and must stay byte-for-byte what the engine wrote — a test pins the raw `\r` surviving. Where no pseudo-terminal can be opened — Windows, a restricted environment — the fallback writes stdout to the log file directly, no worse than the capture did before, and the engine is told `NO_COLOR` the same way; a test stands the opening in for with a failure to keep that branch alive. The pump always drains — the throttle delays the log's writes, never the reads, so the engine can never wedge on a full terminal — and the log file closes only after the pump's final record, never under it. The master is not closed when the engine exits: closing it discards bytes the engine wrote just before exiting that the pump has not read yet (on Linux the read returns `EIO` once every slave fd is closed, and an early close loses the tail — the cause of the `TestSupervisorPTYCapture` flake on CI). The supervisor waits for the pump to reach end of stream, and closes the master itself only after `ptyDrainTimeout`, which covers a child of the engine that keeps the slave open. -**The generation speed is read where the capture already assembles lines, and the wiring order is the whole feature.** llama.cpp prints its instantaneous rate into stderr's `print_timing` lines; the supervisor wraps its log-file sink in a `lineTee` (`tee.go`) that writes every byte to the file untouched and hands each complete line to `Supervisor.OnOutput`, so both capture paths — stderr straight through, pty stdout through the normaliser — feed the parser with no second reader of the log. `OnOutput` is read as `Supervisor.Start` builds the sink, so a daemon must set it *before* starting: wired afterwards, the tee is simply never there and every line is silently lost (this was the first implementation's bug). The parser reads `tg = t/s` only — `tg\s*=` cannot match `tg_3s =`, so the three-second average and prompt rates never read as the current rate — and a tracker with two clocks splits the answer: the sampler's tick folds a history point for the figures its interval saw (strictly after the previous tick: a point is an observation, never a continuation), while a metrics read reports the figure only until one interval of quiet ages it out. Both start engines reset tracker, baseline and history together, so one engine's rate never rides the next engine's report. +**The generation speed is read where the capture already assembles lines, and the wiring order is the whole feature.** llama.cpp prints its generation rates into stderr's `print_timing` lines; the supervisor wraps its log-file sink in a `lineTee` (`tee.go`) that writes every byte to the file untouched and hands each complete line to `Supervisor.OnOutput`, so both capture paths — stderr straight through, pty stdout through the normaliser — feed the parser with no second reader of the log. `OnOutput` is read as `Supervisor.Start` builds the sink, so a daemon must set it *before* starting: wired afterwards, the tee is simply never there and every line is silently lost (this was the first implementation's bug). The parser reads the line's three-second rate `tg_3s = t/s` where it carries a usable one and falls back to the instantaneous `tg = t/s` otherwise — each pattern is narrow enough to answer only for its own label (`\btg\s*=` cannot match `tg_3s =`, the underscore is a word character so `print_tg_3s` matches nothing, and a longer `tg_30s` breaks the literal), an unusable three-second figure — the `0.00` or `-nan` before a slot's first token — falls through rather than quenching the line, and prompt rates never read as the generation rate — and a tracker with two clocks splits the answer: the sampler's tick folds a history point for the figures its interval saw (strictly after the previous tick: a point is an observation, never a continuation), while a metrics read reports the figure only until one interval of quiet ages it out. Both start engines reset tracker, baseline and history together, so one engine's rate never rides the next engine's report. **Calling `prog.Send` from inside `Update` deadlocks the program.** The event loop reads its own channel on the goroutine that calls `Update`, so a command that hands a message back through `prog.Send` while `Update` is on the stack waits for a reader that is waiting for it. The board hung on exactly this: pressing Enter on the form's last field, or `a`/`x` on a card, and the whole TUI went still — no spinner, no keystrokes, Ctrl-C ignored. Every message from work that starts inside `Update` must *return* through the loop instead: `tea.Batch(workCmd, spinCmd)` delivers each command's messages normally, and a repaint chain re-arms through its own returned `tea.Tick`. The tests guard this by landing commands through the real program loop, not by calling `Update` and discarding the command. ## Dashboard (`fleet_dashboard.go` and friends) diff --git a/docs/openapi.yaml b/docs/openapi.yaml index a0a6c0c6..36d43661 100644 --- a/docs/openapi.yaml +++ b/docs/openapi.yaml @@ -422,7 +422,9 @@ components: description: | The engine's own generation rate in tokens per second, parsed from the timing lines it prints into its captured output - (llama.cpp's print_timing `tg` figure today). Present only while + (llama.cpp's print_timing figure today — its three-second + `tg_3s` rate where the line carries a usable one, its whole-task + `tg` average otherwise). Present only while the engine runs and has printed a figure within the last sampler interval; absent — never zero — for a stopped or quiet engine, an engine that prints no rate, and a daemon that predates the diff --git a/internal/daemon/speed_test.go b/internal/daemon/speed_test.go index aea7e981..24b6e0ae 100644 --- a/internal/daemon/speed_test.go +++ b/internal/daemon/speed_test.go @@ -60,7 +60,8 @@ func TestEngineSpeedFoldAndLapse(t *testing.T) { // TestSpeedEndToEnd runs a fake engine that prints llama.cpp's timing line, // and reads the figure back through the capture hook, the sampler fold and -// the metrics reply — every seam in one wire. +// the metrics reply — every seam in one wire. The line carries both rates, so +// what comes back is the three-second figure, never the whole-task average. func TestSpeedEndToEnd(t *testing.T) { d := testDaemon(t, `trap 'exit 0' TERM echo "slot print_timing: id 0 | task 326 | n_gen = 9438, tg = 3.87 t/s, tg_3s = 5.29 t/s" >&2 @@ -87,15 +88,15 @@ while true; do sleep 0.05; done`) if len(hist) != 1 { t.Fatalf("history = %d samples, want 1", len(hist)) } - if hist[0].Speed == nil || *hist[0].Speed != 3.87 { - t.Errorf("sample speed = %v, want 3.87", hist[0].Speed) + if hist[0].Speed == nil || *hist[0].Speed != 5.29 { + t.Errorf("sample speed = %v, want 5.29", hist[0].Speed) } // The running metrics reply carries the current figure while it is fresh // (the clock is pinned at baseTime, and the figure is observed "now"). stats := d.Metrics(context.Background()) - if stats.Speed == nil || *stats.Speed != 3.87 { - t.Fatalf("metrics speed = %v, want 3.87", stats.Speed) + if stats.Speed == nil || *stats.Speed != 5.29 { + t.Fatalf("metrics speed = %v, want 5.29", stats.Speed) } // A tick's worth of quiet later — same figure in hand, no new one — the @@ -119,7 +120,7 @@ while true; do sleep 0.05; done`) t.Errorf("a stopped engine still reports %v, want no current figure", stats.Speed) } hist = d.hist.snapshot() - if len(hist) != 2 || hist[0].Speed == nil || *hist[0].Speed != 3.87 { + if len(hist) != 2 || hist[0].Speed == nil || *hist[0].Speed != 5.29 { t.Errorf("history after a stop = %+v, want the taken point retained", hist) } } @@ -164,6 +165,36 @@ while true; do sleep 0.05; done`) } } +// TestSpeedThreeSecondOnlyLineFolds pins the parser's precedence through the +// daemon seam: a timing line carrying only the three-second rate reaches the +// fold and the metrics reply as that figure, so an engine that prints no +// instantaneous tg still answers "how fast is it generating?". +func TestSpeedThreeSecondOnlyLineFolds(t *testing.T) { + d := testDaemon(t, `trap 'exit 0' TERM +while true; do sleep 0.05; done`) + d.Now = func() time.Time { return baseTime } + + if err := d.Push(inference.DeployConfig{Runner: "llamacpp", ModelID: "m"}); err != nil { + t.Fatal(err) + } + if err := d.StartEngine(); err != nil { + t.Fatal(err) + } + defer d.Sup.Stop() + waitForState(t, d.Sup, StateRunning) + + d.Now = func() time.Time { return baseTime.Add(time.Second) } + d.ObserveEngineLine("slot print_timing: id 0 | task 3 | tg_3s = 5.29 t/s") + d.systemSampleOnce(context.Background()) + hist := d.hist.snapshot() + if len(hist) != 1 || hist[0].Speed == nil || *hist[0].Speed != 5.29 { + t.Fatalf("history = %+v, want one sample at the three-second rate", hist) + } + if got := d.Metrics(context.Background()).Speed; got == nil || *got != 5.29 { + t.Errorf("metrics speed = %v, want 5.29", got) + } +} + // TestSpeedForgetsOnStart pins the engine boundary: the second engine's // report answers with its own rates or none, never the first engine's. func TestSpeedForgetsOnStart(t *testing.T) { diff --git a/internal/metrics/metrics.go b/internal/metrics/metrics.go index 67615981..dc26ebd5 100644 --- a/internal/metrics/metrics.go +++ b/internal/metrics/metrics.go @@ -30,7 +30,9 @@ type Stats struct { Errors []string `json:"errors,omitempty"` // Speed is the engine's own generation rate in tokens per second, parsed // from the timing lines it prints into its captured output (llama.cpp's - // print_timing `tg` figure today). Present only while the engine runs and + // print_timing figure today — its three-second `tg_3s` rate where the + // line carries a usable one, its whole-task `tg` average otherwise). + // Present only while the engine runs and // has printed a figure since the last sampler tick: a stopped or quiet // engine has no rate to report, and the old figure of a rate that has // stopped is not an answer to "how fast is it generating?". Absent, not diff --git a/internal/metrics/speed.go b/internal/metrics/speed.go index 0683cac6..3a4d9b11 100644 --- a/internal/metrics/speed.go +++ b/internal/metrics/speed.go @@ -6,28 +6,49 @@ import ( "strconv" ) -// generationSpeed matches the instantaneous generation-rate figure in an -// engine's timing line, e.g. llama.cpp's +// generationSpeed3s and generationSpeed match the generation-rate figures in +// an engine's timing line, e.g. llama.cpp's // // slot print_timing: id 0 | task 326 | n_gen = 9438, tg = 3.87 t/s, tg_3s = 5.29 t/s // -// The figure read is the current rate the engine names `tg`. The pattern is -// deliberately narrow: `tg\s*=` cannot match `tg_3s =` — the underscore that -// must follow `tg` there breaks the `\s*=` that must follow here — and the -// line's other rates (the three-second average, prompt-evaluation speeds) -// carry different labels, so none of them reads as the current rate. -var generationSpeed = regexp.MustCompile(`\btg\s*=\s*([0-9]+(?:\.[0-9]+)?)\s*t/s`) +// The figure read is `tg_3s` where the line carries a usable one and `tg` +// otherwise: the three-second rate answers "how fast is it generating now", +// while `tg` averages the whole task and lags a rate that has changed. Older +// engines print only `tg`, and the fallback keeps them reporting. Both +// patterns are deliberately narrow: `\btg\s*=` cannot match `tg_3s =` — the +// underscore that must follow `tg` there breaks the `\s*=` that must follow +// here — and the line's other rates (prompt-evaluation speeds) carry +// different labels, so none of them reads as the generation rate. +var ( + generationSpeed3s = regexp.MustCompile(`\btg_3s\s*=\s*([0-9]+(?:\.[0-9]+)?)\s*t/s`) + generationSpeed = regexp.MustCompile(`\btg\s*=\s*([0-9]+(?:\.[0-9]+)?)\s*t/s`) +) // ParseGenerationSpeed extracts an engine's self-reported generation speed, // in tokens per second, from one captured output line, reporting whether the // line carried one. llama.cpp's print_timing lines carry it today; an engine // that prints no such line simply never yields a speed — the absent stat, not -// a zero. A figure that is not a plausible positive rate (an unparsable -// number, a zero or negative rate) is no speed either: llama.cpp prints -// nonsense before a slot's first token, and "0 t/s" is indistinguishable -// from the absence that means "not generating". +// a zero. The three-second rate wins wherever it carries a usable figure, and +// the instantaneous figure answers wherever it does not, so a rate that has +// just changed reads now rather than after the task's average catches up. A +// figure that is not a plausible positive rate (an unparsable number, a zero +// or negative rate) is no speed either: llama.cpp prints nonsense before a +// slot's first token, and "0 t/s" is indistinguishable from the absence that +// means "not generating" — so an unusable three-second figure falls through +// to the instantaneous one rather than quenching the line. func ParseGenerationSpeed(line string) (float64, bool) { - m := generationSpeed.FindStringSubmatch(line) + for _, re := range []*regexp.Regexp{generationSpeed3s, generationSpeed} { + if v, ok := firstRate(line, re); ok { + return v, true + } + } + return 0, false +} + +// firstRate reads re's figure from the line, rejecting a value that is not a +// plausible positive rate. +func firstRate(line string, re *regexp.Regexp) (float64, bool) { + m := re.FindStringSubmatch(line) if m == nil { return 0, false } diff --git a/internal/metrics/speed_test.go b/internal/metrics/speed_test.go index 0c990437..67647f83 100644 --- a/internal/metrics/speed_test.go +++ b/internal/metrics/speed_test.go @@ -10,13 +10,13 @@ func TestParseGenerationSpeed(t *testing.T) { found bool }{ { - name: "llama.cpp print_timing line as the engine prints it", + name: "llama.cpp print_timing line reads its three-second rate", line: "slot print_timing: id 0 | task 326 | n_gen = 9438, tg = 3.87 t/s, tg_3s = 5.29 t/s", - want: 3.87, + want: 5.29, found: true, }, { - name: "a whole-number rate", + name: "an older engine's tg line falls back and reads", line: "slot print_timing: id 0 | task 1 | tg = 42 t/s", want: 42, found: true, @@ -28,8 +28,28 @@ func TestParseGenerationSpeed(t *testing.T) { found: true, }, { - name: "the average alone is not the current rate", - line: "slot print_timing: id 0 | task 326 | tg_3s = 5.29 t/s", + name: "no spacing around the three-second figure", + line: "tg_3s=12.5 t/s", + want: 12.5, + found: true, + }, + { + name: "the three-second rate alone yields the speed", + line: "slot print_timing: id 0 | task 326 | tg_3s = 5.29 t/s", + want: 5.29, + found: true, + }, + { + name: "an unusable three-second figure falls back to tg", + line: "slot print_timing: id 0 | tg_3s = 0.00 t/s, tg = 6.20 t/s", + want: 6.20, + found: true, + }, + { + name: "the nonsense before the first token falls back too", + line: "slot print_timing: id 0 | tg_3s = -nan t/s, tg = 6.20 t/s", + want: 6.20, + found: true, }, { name: "a prompt-evaluation rate is not a generation rate", @@ -43,10 +63,18 @@ func TestParseGenerationSpeed(t *testing.T) { name: "the nonsense before the first token yields nothing", line: "slot print_timing: id 0 | tg = -nan t/s", }, + { + name: "a zero three-second rate is the absence too", + line: "slot print_timing: id 0 | tg_3s = 0.00 t/s", + }, { name: "a rate label without the t/s unit is not the figure", line: "some other log line mentioning tg = 100", }, + { + name: "a three-second label without the t/s unit is not the figure", + line: "some other log line mentioning tg_3s = 100", + }, { name: "an unrelated line carries no speed", line: "registering model 'Qwen3.6-27B'", @@ -55,6 +83,14 @@ func TestParseGenerationSpeed(t *testing.T) { name: "an identifier ending in tg does not match", line: "slot print_tg = 5 t/s", }, + { + name: "an identifier ending in tg_3s does not match", + line: "slot print_tg_3s = 5 t/s", + }, + { + name: "a longer average label does not masquerade as tg_3s", + line: "slot print_timing: id 0 | tg_30s = 5.00 t/s", + }, } for _, c := range cases { t.Run(c.name, func(t *testing.T) { @@ -69,11 +105,11 @@ func TestParseGenerationSpeed(t *testing.T) { } } -func TestParseGenerationSpeedPrefersInstantaneous(t *testing.T) { - // Both figures on one line: the instantaneous tg, never the tg_3s average. - line := "99.999 I slot print_timing: id 0 | task 9 | n_gen = 10, tg = 7.15 t/s, tg_3s = 99.99 t/s" +func TestParseGenerationSpeedPrefersThreeSecondRate(t *testing.T) { + // Both figures on one line: the three-second tg_3s, never the whole-task tg average. + line := "99.999 I slot print_timing: id 0 | task 9 | n_gen = 10, tg = 7.15 t/s, tg_3s = 4.02 t/s" got, ok := ParseGenerationSpeed(line) - if !ok || got != 7.15 { - t.Errorf("ParseGenerationSpeed = %v/%v, want 7.15/true", got, ok) + if !ok || got != 4.02 { + t.Errorf("ParseGenerationSpeed = %v/%v, want 4.02/true", got, ok) } } diff --git a/openspec/changes/archive/2026-11-02-prefer-tg-3s-generation-speed/.openspec.yaml b/openspec/changes/archive/2026-11-02-prefer-tg-3s-generation-speed/.openspec.yaml new file mode 100644 index 00000000..a7587c5f --- /dev/null +++ b/openspec/changes/archive/2026-11-02-prefer-tg-3s-generation-speed/.openspec.yaml @@ -0,0 +1,2 @@ +schema: spec-driven +created: 2026-11-02 diff --git a/openspec/changes/archive/2026-11-02-prefer-tg-3s-generation-speed/design.md b/openspec/changes/archive/2026-11-02-prefer-tg-3s-generation-speed/design.md new file mode 100644 index 00000000..93d057c3 --- /dev/null +++ b/openspec/changes/archive/2026-11-02-prefer-tg-3s-generation-speed/design.md @@ -0,0 +1,67 @@ +# Design + +## Context + +`ParseGenerationSpeed` (`internal/metrics/speed.go`) turns one captured engine +line into a speed reading. It is one narrow regex over `tg = t/s`, built to +*exclude* `tg_3s` — `\btg\s*=` cannot match `tg_3s =` because the underscore +breaks the `\s*=` — plus a validity filter (unparsable, `NaN`, `±Inf`, or +`≤ 0` is no speed: llama.cpp prints nonsense before a slot's first token). Its +caller is the daemon's `lineTee` → `engineSpeed` fold; `internal/daemon`, the +serve view, and the fleet surfaces all consume the single `Speed` figure, so +this function is the only place the choice of label is made. See proposal.md +for why the reading should move to `tg_3s`. + +## Goals / Non-Goals + +**Goals:** + +- One parsing entry point with unchanged signature — callers, the fold, and + every wire format are untouched. +- Older llama.cpp builds (no `tg_3s`) and any other engine printing `tg` + behave exactly as today. + +**Non-Goals:** + +- No change to the fold, the lapse window, history, or rendering — a `tg_3s` + reading and a `tg` reading are the same number in the same slot. +- No per-engine label table or configuration: the line's own labels decide. + +## Decisions + +**Second regex tried first, not one alternation.** Add +`\btg_3s\s*=\s*([0-9]+(?:\.[0-9]+)?)\s*t/s` and try it before the existing +`tg` pattern, sharing the existing validity filter via a small helper (`firstRate(line, re)`). An alternation like `(?:tg_3s|tg)\s*=` would +make the primary pattern's deliberate narrowness a correctness dependency of +the fallback (`tg` inside `tg_3s` must never match, and the "identifier ending +in tg" test exists precisely because that boundary is load-bearing); two +explicit patterns keep each case separately testable and read truer to the +spec sentence "the three-second rate where usable, else the instantaneous +one". Chosen over scanning for both and comparing positions on the line — +label precedence, not column order, is what the spec requires. + +**"Usable" decides the fallback, not mere presence.** A `tg_3s` that is +present but unusable (`0.00`, `-nan`) falls through to `tg` rather than +yielding nothing. The alternative — presence wins, so `tg_3s = -nan` kills the +reading even beside a good `tg` — throws away a usable figure the current code +would have read, regressing older-behaviour cases for no spec gain; the +validity filter already treats those prints as the engine not knowing yet, and +"not knowing" is exactly the case the fallback is for. + +**Keep `\btg\s*=` byte-identical.** The fallback is the current pattern +unchanged, so every existing negative test (prompt rates, `pp.*t/s`, +identifiers ending in `tg`, `0 t/s`, `-nan`) still pins the same boundary. +`\b` before `tg_3s` gives the same protection for the new pattern: `_` is a +word character, so `n_tg_3s` cannot match. + +## Risks / Trade-offs + +- [`tg_3s` is noisier than a task average near window edges — a 3 s figure + can dip while the next batch warms up] → The surface already shows a live + sparkline with a lapse window; jitter is the honest picture of "now", and + the fold reports the latest observation, not a smoothed one, exactly as + before. +- [A future engine label shaped like `tg_3s` (e.g. `tg_30s`) could be read as + the three-second rate] → `tg_3s\s*=` cannot match `tg_30s =` (the `0` + breaks the literal); a scenario in the delta covers only the two real + labels, and any new label is a deliberate spec change. diff --git a/openspec/changes/archive/2026-11-02-prefer-tg-3s-generation-speed/proposal.md b/openspec/changes/archive/2026-11-02-prefer-tg-3s-generation-speed/proposal.md new file mode 100644 index 00000000..85f81c71 --- /dev/null +++ b/openspec/changes/archive/2026-11-02-prefer-tg-3s-generation-speed/proposal.md @@ -0,0 +1,45 @@ +# Proposal + +## Why + +llama.cpp's `tg` figure averages the whole generation task, so the dashboard's +Speed row lags badly when the rate changes — a model that just sped up (or +slowed under contention) keeps showing its old pace for minutes. llama.cpp now +also prints `tg_3s`, a three-second rolling rate that answers "how fast is it +generating *now*", which is exactly what the Speed row claims to show — but +today's parser deliberately reads only `tg` and never `tg_3s`. + +## What Changes + +- The engine-output speed parser reads `tg_3s` when the line carries it, and + falls back to `tg` when it does not or when the `tg_3s` figure is not a + usable rate. Engines whose llama.cpp predates `tg_3s` (and other engines + printing `tg`) keep reporting speed unchanged. +- The rendered Speed row therefore reflects the recent rate rather than the + since-task average. No change to rendering, folding, history, or lapse + behaviour — only which figure on the line is read. + +## Capabilities + +### New Capabilities + +(none) + +### Modified Capabilities + +- `engine-metrics`: "Generation speed from engine output" — the figure read + becomes the three-second rate `tg_3s` where the line carries a usable one, + falling back to `tg`; the scenario "An average is not the current rate" + keeps its name but its rejected average becomes the whole-task `tg` + instead of `tg_3s`. + +## Impact + +- `internal/metrics/speed.go` — one added `tg_3s` pattern and a fallback in + `ParseGenerationSpeed`. +- `internal/metrics/speed_test.go`, `internal/daemon/speed_test.go` — + expectations for lines carrying both figures, and the "average yields + nothing" cases. +- `docs/maintainer/internals.md` — the paragraph pinning the parser to + `tg`-only. +- No API, wire-format, or rendering changes: the stat's shape is unchanged. diff --git a/openspec/changes/archive/2026-11-02-prefer-tg-3s-generation-speed/specs/engine-metrics/spec.md b/openspec/changes/archive/2026-11-02-prefer-tg-3s-generation-speed/specs/engine-metrics/spec.md new file mode 100644 index 00000000..b214f7fd --- /dev/null +++ b/openspec/changes/archive/2026-11-02-prefer-tg-3s-generation-speed/specs/engine-metrics/spec.md @@ -0,0 +1,39 @@ +# Spec Delta + +## Modified Requirements + +### Requirement: Generation speed from engine output + +The system SHALL parse a generation speed — tokens per second — from the engine's own captured output lines. An engine that reports the figure in its structured log, llama.cpp's `print_timing` lines carrying `tg = 3.87 t/s` and `tg_3s = 5.29 t/s` today, yields it. The figure read SHALL be the line's three-second rate (`tg_3s`) where the line carries a usable one, and SHALL fall back to the instantaneous rate (`tg`) where it carries none or the three-second figure is not usable — the shorter window answers "how fast is it generating now", which is the figure the speed is for, while `tg` averages the whole task and lags a rate that has changed. Rates the line carries under other labels — prompt-evaluation speed among them — SHALL not be read as it. + +The speed is an optional stat on the same terms as every other: an engine whose metrics carry no such figure and whose output carries no timing line, and an engine run where its output is not captured, report the speed absent rather than reported as zero. + +#### Scenario: A timing line yields the speed + +- **WHEN** a captured engine line carries `tg = 12.34 t/s` and no `tg_3s` figure +- **THEN** the collected reading carries a generation speed of 12.34 tokens per second + +#### Scenario: An average is not the current rate + +- **WHEN** a captured line carries both `tg = 3.87 t/s` and `tg_3s = 5.29 t/s` +- **THEN** the collected reading carries 5.29 tokens per second — the three-second rate, and not the whole-task average `tg` names + +#### Scenario: An engine without timing lines reports none + +- **WHEN** metrics are collected while the running engine's output carries no timing line +- **THEN** the result omits the generation speed rather than reporting zero + +#### Scenario: A line without an instantaneous rate still yields the speed + +- **WHEN** a captured line carries only a `tg_3s = 5.29 t/s` figure +- **THEN** the collected reading carries a generation speed of 5.29 tokens per second + +#### Scenario: An unusable three-second figure falls back + +- **WHEN** a captured line carries an unusable `tg_3s` figure — zero or an unparsable number — beside a usable `tg` figure +- **THEN** the collected reading carries the `tg` rate + +#### Scenario: Other rates yield nothing + +- **WHEN** a captured line carries a prompt-evaluation rate with no `tg` or `tg_3s` figure +- **THEN** no speed is yielded from that line diff --git a/openspec/changes/archive/2026-11-02-prefer-tg-3s-generation-speed/tasks.md b/openspec/changes/archive/2026-11-02-prefer-tg-3s-generation-speed/tasks.md new file mode 100644 index 00000000..b0965d18 --- /dev/null +++ b/openspec/changes/archive/2026-11-02-prefer-tg-3s-generation-speed/tasks.md @@ -0,0 +1,19 @@ +# Tasks + +## 1. Parse the three-second rate + +- [x] 1.1 In `internal/metrics/speed.go`, add the `tg_3s` pattern tried before the unchanged `tg` pattern, sharing the validity filter, and rewrite the pattern/function doc comments to state the precedence. Verify with `go test ./internal/metrics/`. +- [x] 1.2 Rework `internal/metrics/speed_test.go` against the delta spec scenarios: `tg_3s` wins when both are present, a `tg_3s`-only line yields its figure, an unusable `tg_3s` (`0.00`, `-nan`) falls back to a usable `tg`, prompt-rate-only lines still yield nothing, and existing negatives (`n_tg`-style identifiers, missing `t/s`, zero/negative) stay pinned. Verify with `go test ./internal/metrics/ -run Speed -v`. + +## 2. Update the consumers' expectations and notes + +- [x] 2.1 Update `internal/daemon/speed_test.go`: the end-to-end fake prints both figures, so the expected reading becomes the `tg_3s` figure (5.29, not 3.87), and the "instantaneous preferred" comment reverses. Verify with `go test ./internal/daemon/ -run Speed`. +- [x] 2.2 Update the `Speed` field comments in `internal/metrics/metrics.go` that name the `tg` figure as what is read. Verify by inspection alongside the green `internal/metrics` suite. + +## 3. Documentation + +- [x] 3.1 Update the generation-speed paragraph in `docs/maintainer/internals.md` to describe the two-pattern precedence (`tg_3s` where usable, else `tg`) instead of the `tg`-only rule. Verify the paragraph reads true against the shipped parser. + +## 4. Integration checks + +- [x] 4.1 Run `gofmt -l .`, `go vet ./...`, and `go test ./... -cover`; verify formatting and vet are clean, the suite is green, and total coverage stays >= 80%. diff --git a/openspec/specs/engine-metrics/spec.md b/openspec/specs/engine-metrics/spec.md index ca084e7f..fb6b9b1d 100644 --- a/openspec/specs/engine-metrics/spec.md +++ b/openspec/specs/engine-metrics/spec.md @@ -226,21 +226,36 @@ not a zero — true of the rendered output as it is of the collected one. ### Requirement: Generation speed from engine output -The system SHALL parse a generation speed — tokens per second — from the engine's own captured output lines. An engine that reports the figure in its structured log, llama.cpp's `print_timing` lines carrying `tg = 3.87 t/s` today, yields it; the figure read SHALL be the instantaneous one the line names for the current rate, and a line's other rate figures — a trailing three-second average, prompt-evaluation speed — SHALL not be read as it. +The system SHALL parse a generation speed — tokens per second — from the engine's own captured output lines. An engine that reports the figure in its structured log, llama.cpp's `print_timing` lines carrying `tg = 3.87 t/s` and `tg_3s = 5.29 t/s` today, yields it. The figure read SHALL be the line's three-second rate (`tg_3s`) where the line carries a usable one, and SHALL fall back to the instantaneous rate (`tg`) where it carries none or the three-second figure is not usable — the shorter window answers "how fast is it generating now", which is the figure the speed is for, while `tg` averages the whole task and lags a rate that has changed. Rates the line carries under other labels — prompt-evaluation speed among them — SHALL not be read as it. The speed is an optional stat on the same terms as every other: an engine whose metrics carry no such figure and whose output carries no timing line, and an engine run where its output is not captured, report the speed absent rather than reported as zero. #### Scenario: A timing line yields the speed -- **WHEN** a captured engine line carries `tg = 12.34 t/s` +- **WHEN** a captured engine line carries `tg = 12.34 t/s` and no `tg_3s` figure - **THEN** the collected reading carries a generation speed of 12.34 tokens per second #### Scenario: An average is not the current rate -- **WHEN** a captured line carries only a `tg_3s = 5.29 t/s` figure, or a prompt-evaluation rate, with no instantaneous `tg` figure -- **THEN** no speed is yielded from that line +- **WHEN** a captured line carries both `tg = 3.87 t/s` and `tg_3s = 5.29 t/s` +- **THEN** the collected reading carries 5.29 tokens per second — the three-second rate, and not the whole-task average `tg` names #### Scenario: An engine without timing lines reports none - **WHEN** metrics are collected while the running engine's output carries no timing line - **THEN** the result omits the generation speed rather than reporting zero + +#### Scenario: A line without an instantaneous rate still yields the speed + +- **WHEN** a captured line carries only a `tg_3s = 5.29 t/s` figure +- **THEN** the collected reading carries a generation speed of 5.29 tokens per second + +#### Scenario: An unusable three-second figure falls back + +- **WHEN** a captured line carries an unusable `tg_3s` figure — zero or an unparsable number — beside a usable `tg` figure +- **THEN** the collected reading carries the `tg` rate + +#### Scenario: Other rates yield nothing + +- **WHEN** a captured line carries a prompt-evaluation rate with no `tg` or `tg_3s` figure +- **THEN** no speed is yielded from that line