feat(metrics): read the three-second tg_3s rate for engine speed

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
 

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 = <n> 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 = <n> t/s` where it carries a usable one and falls back to the instantaneous `tg = <n> 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)

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

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) {

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

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
 	}

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)
 	}
 }

openspec/changes/archive/2026-11-02-prefer-tg-3s-generation-speed/.openspec.yaml

@@ -0,0 +1,2 @@
+schema: spec-driven
+created: 2026-11-02