usage: a streamed reply's time to its first token is kept, and its first text's (#196: usage 记录首字延迟（TTFT），用于计算模型的真实生成速度) — usage.jsonl had only a call's whole ms and its out tokens, so how fast a model writes couldn't be told from how long it waited or thought. The reply is now read as it goes to the agent, in the agent's protocol whatever the vendor spoke (Anthropic content_block_delta text/thinking/input_json and a tool_use's start, Chat content/reasoning_content/reasoning/tool_calls, Responses output_text/reasoning/function_call_arguments deltas and a function call's start, Gemini parts), and each record gets ttft_ms to the first content and first_text_ms to the first text, counted from the request as ms is, so ms − ttft_ms is the writing time; a reply that isn't streamed gets neither, and omitempty leaves old records as they were. Only the stream's events up to its first text are read (a JSON reply, or past 8 MB, not at all). Each try in the routing trace keeps its own from when it was sent, so a group that fails over shows which member was slow, and the route, the request log and the Codex backend's relay keep them too. Shown on the Routing page (TTFT in the list, first token / first text / tok/s in a try's story), in the Gateway's request log, and on the Usage page and in magpie usage per model as the mean TTFT and tok/s = out ÷ (ms − ttft) over the answered streamed calls. Tested with fake vendors streaming a gap apart for Anthropic, Chat and Responses, as they came and translated (Chat from Anthropic, Responses from Chat), the ChatGPT backend without a Content-Type, a whole reply, a group whose first member fails (its try untimed, the second's timed from its own start, the request's including the failed try), each protocol's events and split writes, and the summary's sums; the GUI's browser tests pass

internal/gateway/codex_backend.go

@@ -215,7 +215,8 @@ func (s *Server) codexUpstream(w http.ResponseWriter, r *http.Request, rest stri
 	// a turn goes in the Routing view's live trace as the others do, to
 	// the one it can go to: Codex's own sign-in, or its key
 	var tr *Route
-	end := func(status int, msg string, tokens int) {}
+	first := firstToken{start: start} // the reply's first tokens (#196), counted as ms are
+	end := func(status int, msg string, tokens, out int) {}
 	if rest == "/responses" {
 		who := "Codex's own sign-in"
 		if base == codexAPIBase {
@@ -225,11 +226,14 @@ func (s *Server) codexUpstream(w http.ResponseWriter, r *http.Request, rest stri
 		seat := Weighed{ID: "codex", Provider: "openai", Name: "OpenAI", Icon: "openai", Who: who, Kind: "account", Agent: "codex", Model: model}
 		tr = s.trace.begin(Route{Time: start, Agent: agentOf(r), Model: model, Provider: "openai",
 			Order: []Weighed{seat}, Tries: []Try{{ID: seat.ID, Model: model, Start: start}}})
-		end = func(status int, msg string, tokens int) {
+		end = func(status int, msg string, tokens, out int) {
 			ms := time.Since(start).Milliseconds()
+			ttft, text := first.ms()
 			s.trace.update(tr, func(t *Route) {
 				t.Tries[0].Done, t.Tries[0].Status, t.Tries[0].Millis, t.Tries[0].Error = true, status, ms, msg
+				t.Tries[0].TTFT, t.Tries[0].FirstText = ttft, text
 				t.Done, t.Status, t.Error, t.Millis, t.Tokens = true, status, msg, ms, tokens
+				t.Output, t.TTFT, t.FirstText = out, ttft, text
 			})
 		}
 	}
@@ -238,7 +242,7 @@ func (s *Server) codexUpstream(w http.ResponseWriter, r *http.Request, rest stri
 		req, err := http.NewRequestWithContext(r.Context(), r.Method, u, bytes.NewReader(body))
 		if err != nil {
 			writeError(w, provider.Responses, 502, err.Error())
-			end(502, err.Error(), 0)
+			end(502, err.Error(), 0, 0)
 			return
 		}
 		copyHeaders(req.Header, r.Header)
@@ -246,7 +250,7 @@ func (s *Server) codexUpstream(w http.ResponseWriter, r *http.Request, rest stri
 		req.Header.Del("Accept-Encoding")
 		if res, err = s.client.Do(req); err != nil {
 			writeError(w, provider.Responses, 502, "OpenAI: "+err.Error())
-			end(502, "OpenAI: "+err.Error(), 0)
+			end(502, "OpenAI: "+err.Error(), 0, 0)
 			return
 		}
 		if rest != "/responses" || tries >= 3 || (res.StatusCode != 400 && res.StatusCode != 404) {
@@ -275,7 +279,7 @@ func (s *Server) codexUpstream(w http.ResponseWriter, r *http.Request, rest stri
 		s.record(Call{Time: start, From: provider.Responses, To: provider.Responses, Model: modelOf(body),
 			Provider: "openai", Agent: agentOf(r), Status: res.StatusCode,
 			Millis: time.Since(start).Milliseconds(), Error: res.Status})
-		end(res.StatusCode, res.Status, 0)
+		end(res.StatusCode, res.Status, 0, 0)
 		return
 	}
 	for k, vs := range res.Header {
@@ -300,6 +304,7 @@ func (s *Server) codexUpstream(w http.ResponseWriter, r *http.Request, rest stri
 		if n > 0 {
 			if sniff != nil {
 				sniff.write(buf[:n])
+				first.see(buf[:n])
 			}
 			if _, werr := w.Write(buf[:n]); werr != nil {
 				break
@@ -318,17 +323,18 @@ func (s *Server) codexUpstream(w http.ResponseWriter, r *http.Request, rest stri
 	call := Call{Time: start, From: provider.Responses, To: provider.Responses, Model: modelOf(body),
 		Provider: "openai", Agent: agentOf(r), Status: res.StatusCode,
 		Millis: time.Since(start).Milliseconds()}
+	call.TTFT, call.FirstText = first.ms()
 	var uu Usage
 	uu.add(sniff.usage())
 	call.Usage = uu
 	if res.StatusCode >= 400 {
 		call.Error = res.Status
 	}
-	end(call.Status, call.Error, uu.Input+uu.Output+uu.CacheRead+uu.CacheWrite)
+	end(call.Status, call.Error, uu.Input+uu.Output+uu.CacheRead+uu.CacheWrite, uu.Output)
 	s.record(call)
 	usage.Append(usage.Record{Time: start, Agent: call.Agent, Provider: call.Provider, Host: provider.HostOf(base), Model: call.Model,
 		Input: uu.Input, Output: uu.Output, CacheRead: uu.CacheRead, CacheWrite: uu.CacheWrite,
-		Reasoning: uu.Reasoning, Millis: call.Millis, Status: call.Status, Session: sessionOf(r.Header)})
+		Reasoning: uu.Reasoning, Millis: call.Millis, TTFT: call.TTFT, FirstText: call.FirstText, Status: call.Status, Session: sessionOf(r.Header)})
 }
 
 // unreadableItem is the item OpenAI's refusal names: sealed content it

internal/gateway/fallback.go

@@ -474,10 +474,12 @@ type holdWriter struct {
 
 	ended bool   // the stream's last event was written: the reply is whole
 	tail  []byte // the end of the last write, for a marker split across two
+
+	first firstToken // when its first content and text came (#196)
 }
 
 func newHoldWriter(w http.ResponseWriter, hold bool) *holdWriter {
-	return &holdWriter{w: w, hold: hold, header: http.Header{}}
+	return &holdWriter{w: w, hold: hold, header: http.Header{}, first: firstToken{start: time.Now()}}
 }
 
 func (h *holdWriter) Header() http.Header { return h.header }
@@ -513,6 +515,7 @@ func (h *holdWriter) Write(b []byte) (int, error) {
 		h.WriteHeader(http.StatusOK)
 	}
 	h.see(b)
+	h.first.see(b)
 	if h.passing {
 		return h.w.Write(b)
 	}

internal/gateway/gateway.go

@@ -153,21 +153,26 @@ func Serving() (running, window bool) {
 
 // Call is one request the gateway handled, for the status views.
 type Call struct {
-	Time              time.Time         `json:"time"`
-	Agent             string            `json:"agent"` // who called, from the client's User-Agent
-	Model             string            `json:"model"`
-	Provider          string            `json:"provider"`
-	From              provider.Protocol `json:"from"`
-	To                provider.Protocol `json:"to"`
-	Status            int               `json:"status"`
-	Millis            int64             `json:"ms"`
-	Error             string            `json:"error,omitempty"`
-	Fallback          string            `json:"fallback,omitempty"` // providers that failed first, and why
-	Usage             Usage             `json:"usage"`
-	RequestBody       string            `json:"requestBody,omitempty"`
-	ResponseBody      string            `json:"responseBody,omitempty"`
-	RequestTruncated  bool              `json:"requestTruncated,omitempty"`
-	ResponseTruncated bool              `json:"responseTruncated,omitempty"`
+	Time     time.Time         `json:"time"`
+	Agent    string            `json:"agent"` // who called, from the client's User-Agent
+	Model    string            `json:"model"`
+	Provider string            `json:"provider"`
+	From     provider.Protocol `json:"from"`
+	To       provider.Protocol `json:"to"`
+	Status   int               `json:"status"`
+	Millis   int64             `json:"ms"`
+	// TTFT: ms from the request to its reply's first content — text,
+	// reasoning or a tool call — and FirstText to its first text, when
+	// it was streamed (#196)
+	TTFT              int64  `json:"ttft,omitempty"`
+	FirstText         int64  `json:"firstText,omitempty"`
+	Error             string `json:"error,omitempty"`
+	Fallback          string `json:"fallback,omitempty"` // providers that failed first, and why
+	Usage             Usage  `json:"usage"`
+	RequestBody       string `json:"requestBody,omitempty"`
+	ResponseBody      string `json:"responseBody,omitempty"`
+	RequestTruncated  bool   `json:"requestTruncated,omitempty"`
+	ResponseTruncated bool   `json:"responseTruncated,omitempty"`
 }
 
 // Server is the gateway.
@@ -882,6 +887,7 @@ func (s *Server) serve(w http.ResponseWriter, r *http.Request, from provider.Pro
 		call.Provider, call.To, call.Usage = c.p.ID, "", Usage{}
 		where = c.p.Where()
 		began := time.Now()
+		hw.first.start = began
 		attemptBody := body
 		if from == provider.Responses {
 			// reasoning another sealed, which this one refused earlier in
@@ -945,6 +951,10 @@ func (s *Server) serve(w http.ResponseWriter, r *http.Request, from provider.Pro
 			call.Status, call.Error = hw.failure, c.p.Name+": "+hw.failMsg
 		}
 		try := Try{ID: c.rest, Model: c.model, Effort: sent, Picked: picked, Fixed: c.effort, Start: began, Done: true, Status: call.Status, Millis: time.Since(began).Milliseconds(), Error: call.Error}
+		try.TTFT, try.FirstText = hw.first.ms()
+		// the request's, from when it came as its ms are: the time before
+		// this try, the ones that failed first, is in it
+		call.TTFT, call.FirstText = sinceStart(began.Sub(start), hw.first.first), sinceStart(began.Sub(start), hw.first.text)
 		if r.Context().Err() != nil && !hw.ended {
 			// the agent went away: nobody failed, and nobody else is asked
 			call.Status, call.Error = 499, "the agent canceled the request"
@@ -1030,16 +1040,26 @@ func (s *Server) serve(w http.ResponseWriter, r *http.Request, from provider.Pro
 	s.trace.update(tr, func(t *Route) {
 		t.Done, t.Status, t.Error, t.Millis = true, call.Status, call.Error, call.Millis
 		t.Tokens = call.Usage.Input + call.Usage.Output + call.Usage.CacheRead + call.Usage.CacheWrite
+		t.Output, t.TTFT, t.FirstText = call.Usage.Output, call.TTFT, call.FirstText
 	})
 	s.record(call)
 	if call.To != "" {
 		usage.Append(usage.Record{Time: start, Agent: call.Agent, Provider: call.Provider, Host: where, Model: model,
 			Input: call.Usage.Input, Output: call.Usage.Output, CacheRead: call.Usage.CacheRead,
 			CacheWrite: call.Usage.CacheWrite, Reasoning: call.Usage.Reasoning, Effort: sent, Millis: call.Millis, Status: call.Status,
-			Session: sessionOf(r.Header)})
+			TTFT: call.TTFT, FirstText: call.FirstText, Session: sessionOf(r.Header)})
 	}
 }
 
+// sinceStart is a time d into a try that began before into the request,
+// as ms from the request's start; 0 for none.
+func sinceStart(before, d time.Duration) int64 {
+	if d <= 0 {
+		return 0
+	}
+	return (before + d).Milliseconds()
+}
+
 // attempt sends a request to one provider. call.To stays empty when the
 // provider has no endpoint to send it to.
 func (s *Server) attempt(w http.ResponseWriter, r *http.Request, from provider.Protocol, p provider.Provider, model string, body []byte, call *Call) (int, string) {

internal/gateway/trace.go

@@ -43,6 +43,12 @@ type Route struct {
 	Error    string       `json:"error,omitempty"`
 	Millis   int64        `json:"ms,omitempty"`
 	Tokens   int          `json:"tokens,omitempty"`
+	Output   int          `json:"out,omitempty"` // of Tokens, the reply's
+	// TTFT: ms from the request to its reply's first content (text,
+	// reasoning or a tool call), FirstText to its first text, as Millis
+	// counts: streamed replies only (#196)
+	TTFT      int64 `json:"ttft,omitempty"`
+	FirstText int64 `json:"firstText,omitempty"`
 }
 
 // GroupRef is the routing group a request asked for.
@@ -145,10 +151,14 @@ type Try struct {
 	Done   bool      `json:"done"`
 	Status int       `json:"status,omitempty"`
 	Millis int64     `json:"ms,omitempty"`
-	Fail   string    `json:"fail,omitempty"` // why it failed, as rest tells it
-	Error  string    `json:"error,omitempty"`
-	Rest   *Rest     `json:"rest,omitempty"`  // how long it now sits out; none when it was the last to try
-	Again  int64     `json:"again,omitempty"` // ms waited before it was tried again, the last one left
+	// TTFT: ms from Start to its reply's first content, FirstText to its
+	// first text, when it streamed any (#196)
+	TTFT      int64  `json:"ttft,omitempty"`
+	FirstText int64  `json:"firstText,omitempty"`
+	Fail      string `json:"fail,omitempty"` // why it failed, as rest tells it
+	Error     string `json:"error,omitempty"`
+	Rest      *Rest  `json:"rest,omitempty"`  // how long it now sits out; none when it was the last to try
+	Again     int64  `json:"again,omitempty"` // ms waited before it was tried again, the last one left
 }
 
 type planned struct {

internal/gateway/ttft.go

@@ -0,0 +1,198 @@
+package gateway
+
+// Time to first token (#196): how long a streamed reply took to begin —
+// the first of its text, reasoning or a tool call — and to show its first
+// text, so how fast a model writes can be told from how long it thought
+// or waited. Read off the stream as it goes to the agent, in the agent's
+// protocol, whichever the vendor spoke: one place for every way a reply
+// comes, translated or not. A reply that isn't streamed isn't timed.
+
+import (
+	"bytes"
+	"encoding/json"
+	"time"
+)
+
+// firstMost is the most of a stream read for its first tokens: a reply
+// that is all tool calls has no text to wait for.
+const firstMost = 8 << 20
+
+// firstToken times a stream's first content and first text from start.
+type firstToken struct {
+	start time.Time
+	first time.Duration // to the first content; 0 until it comes
+	text  time.Duration // to the first text
+	off   bool          // not a stream, or read as far as it is
+	began bool
+	read  int
+	pend  []byte
+}
+
+// see reads what was written of the reply.
+func (f *firstToken) see(b []byte) {
+	if f.off || len(b) == 0 {
+		return
+	}
+	if !f.began {
+		// a JSON reply is no stream
+		if t := bytes.TrimLeft(b, " \t\r\n"); len(t) == 0 {
+			return
+		} else if t[0] == '{' || t[0] == '[' {
+			f.off = true
+			return
+		}
+		f.began = true
+	}
+	if f.read += len(b); f.read > firstMost {
+		f.off, f.pend = true, nil
+		return
+	}
+	f.pend = append(f.pend, b...)
+	for !f.off {
+		end := eventEnd(f.pend)
+		if end < 0 {
+			break
+		}
+		content, text := firstKind(f.pend[:end])
+		f.pend = f.pend[end:]
+		if !content && !text {
+			continue
+		}
+		d := max(time.Since(f.start), time.Millisecond)
+		if f.first == 0 {
+			f.first = d
+		}
+		if text {
+			f.text = d
+			f.off, f.pend = true, nil // all there is to know
+		}
+	}
+	if len(f.pend) == 0 {
+		f.pend = nil
+	}
+}
+
+// ms are the two as milliseconds from start, 0 for none.
+func (f *firstToken) ms() (first, text int64) {
+	return f.first.Milliseconds(), f.text.Milliseconds()
+}
+
+// firstKind says whether a server-sent event of a reply, in any protocol an
+// agent speaks, carries content — text, reasoning or a tool call — and
+// whether that is text the reader sees.
+func firstKind(ev []byte) (content, text bool) {
+	var name string
+	var data []byte
+	for _, ln := range bytes.Split(ev, []byte("\n")) {
+		ln = bytes.TrimRight(ln, "\r")
+		switch {
+		case bytes.HasPrefix(ln, []byte("event:")):
+			name = string(bytes.TrimSpace(ln[6:]))
+		case bytes.HasPrefix(ln, []byte("data:")):
+			data = append(data, bytes.TrimSpace(ln[5:])...)
+		}
+	}
+	// only deltas, a tool call's start and Gemini's parts carry any: the
+	// rest go by unread
+	if len(data) == 0 || !(bytes.Contains(data, []byte("delta")) || bytes.Contains(data, []byte(`"parts"`)) ||
+		bytes.Contains(data, []byte("content_block_start")) || bytes.Contains(data, []byte("output_item.added"))) {
+		return false, false
+	}
+	var v struct {
+		Type         string          `json:"type"`
+		Delta        json.RawMessage `json:"delta"` // Anthropic's an object, Responses' a string
+		ContentBlock *struct {
+			Type string `json:"type"`
+		} `json:"content_block"`
+		Item *struct {
+			Type string `json:"type"`
+		} `json:"item"`
+		Choices []struct {
+			Delta struct {
+				Content          json.RawMessage `json:"content"`
+				Refusal          json.RawMessage `json:"refusal"`
+				ReasoningContent json.RawMessage `json:"reasoning_content"`
+				Reasoning        json.RawMessage `json:"reasoning"`
+				ToolCalls        json.RawMessage `json:"tool_calls"`
+				FunctionCall     json.RawMessage `json:"function_call"`
+			} `json:"delta"`
+		} `json:"choices"`
+		Candidates []struct {
+			Content struct {
+				Parts []struct {
+					Text         string          `json:"text"`
+					Thought      bool            `json:"thought"`
+					FunctionCall json.RawMessage `json:"functionCall"`
+				} `json:"parts"`
+			} `json:"content"`
+		} `json:"candidates"`
+	}
+	if json.Unmarshal(data, &v) != nil {
+		return false, false
+	}
+	typ := v.Type
+	if typ == "" {
+		typ = name
+	}
+	switch typ {
+	case "content_block_delta": // Anthropic
+		var d struct {
+			Type        string `json:"type"`
+			Text        string `json:"text"`
+			Thinking    string `json:"thinking"`
+			PartialJSON string `json:"partial_json"`
+		}
+		json.Unmarshal(v.Delta, &d)
+		switch {
+		case d.Text != "":
+			return true, true
+		case d.Thinking != "", d.PartialJSON != "":
+			return true, false
+		}
+		return false, false
+	case "content_block_start":
+		if b := v.ContentBlock; b != nil && (b.Type == "tool_use" || b.Type == "server_tool_use") {
+			return true, false
+		}
+		return false, false
+	case "response.output_text.delta", "response.refusal.delta": // Responses
+		return filled(v.Delta), filled(v.Delta)
+	case "response.reasoning_summary_text.delta", "response.reasoning_text.delta",
+		"response.function_call_arguments.delta", "response.custom_tool_call_input.delta":
+		return filled(v.Delta), false
+	case "response.output_item.added":
+		if it := v.Item; it != nil && (it.Type == "function_call" || it.Type == "custom_tool_call") {
+			return true, false
+		}
+		return false, false
+	}
+	for _, c := range v.Choices { // Chat
+		d := c.Delta
+		if filled(d.Content) || filled(d.Refusal) {
+			return true, true
+		}
+		if filled(d.ReasoningContent) || filled(d.Reasoning) || filled(d.ToolCalls) || filled(d.FunctionCall) {
+			content = true
+		}
+	}
+	for _, c := range v.Candidates { // Gemini
+		for _, p := range c.Content.Parts {
+			switch {
+			case p.Text != "" && !p.Thought:
+				return true, true
+			case p.Text != "", filled(p.FunctionCall):
+				content = true
+			}
+		}
+	}
+	return content, false
+}
+
+// filled is a JSON value with something in it.
+func filled(raw json.RawMessage) bool {
+	switch string(bytes.TrimSpace(raw)) {
+	case "", "null", `""`, "[]", "{}":
+		return false
+	}
+	return true
+}

internal/gateway/ttft_test.go

@@ -0,0 +1,257 @@
+package gateway
+
+import (
+	"io"
+	"net/http"
+	"net/http/httptest"
+	"strings"
+	"testing"
+	"time"
+
+	"github.com/yetone/magpie/internal/provider"
+	"github.com/yetone/magpie/internal/usage"
+)
+
+// paced is a vendor that streams its events a gap apart, the first at
+// once, or fails with a status after the gap.
+type paced struct {
+	events []string
+	gap    time.Duration
+	fail   int
+}
+
+func (p *paced) ServeHTTP(w http.ResponseWriter, r *http.Request) {
+	io.ReadAll(r.Body)
+	if p.fail != 0 {
+		time.Sleep(p.gap)
+		w.Header().Set("Content-Type", "application/json")
+		w.WriteHeader(p.fail)
+		io.WriteString(w, `{"error":{"message":"slow down"}}`)
+		return
+	}
+	w.Header().Set("Content-Type", "text/event-stream")
+	f := w.(http.Flusher)
+	for i, ev := range p.events {
+		if i > 0 && strings.HasPrefix(ev, "~") { // a gap before it
+			time.Sleep(p.gap)
+			ev = ev[1:]
+		}
+		io.WriteString(w, ev+"\n\n")
+		f.Flush()
+	}
+}
+
+// Each: a lead, then reasoning a gap later, then text another gap later,
+// then the end another gap later — 20 tokens written in all.
+var (
+	pacedAnthropic = []string{
+		"event: message_start\ndata: " + `{"type":"message_start","message":{"id":"msg_1","type":"message","role":"assistant","model":"m1","content":[],"usage":{"input_tokens":5,"output_tokens":0}}}`,
+		"event: content_block_start\ndata: " + `{"type":"content_block_start","index":0,"content_block":{"type":"thinking","thinking":""}}`,
+		"event: ping\ndata: " + `{"type":"ping"}`,
+		"~event: content_block_delta\ndata: " + `{"type":"content_block_delta","index":0,"delta":{"type":"thinking_delta","thinking":"hmm"}}`,
+		"event: content_block_stop\ndata: " + `{"type":"content_block_stop","index":0}`,
+		"event: content_block_start\ndata: " + `{"type":"content_block_start","index":1,"content_block":{"type":"text","text":""}}`,
+		"~event: content_block_delta\ndata: " + `{"type":"content_block_delta","index":1,"delta":{"type":"text_delta","text":"hi"}}`,
+		"event: content_block_stop\ndata: " + `{"type":"content_block_stop","index":1}`,
+		"~event: message_delta\ndata: " + `{"type":"message_delta","delta":{"stop_reason":"end_turn"},"usage":{"output_tokens":20}}`,
+		"event: message_stop\ndata: " + `{"type":"message_stop"}`,
+	}
+	pacedChat = []string{
+		`data: {"id":"c1","model":"m1","choices":[{"index":0,"delta":{"role":"assistant","content":""}}]}`,
+		`~data: {"id":"c1","model":"m1","choices":[{"index":0,"delta":{"reasoning_content":"hmm"}}]}`,
+		`~data: {"id":"c1","model":"m1","choices":[{"index":0,"delta":{"content":"hi"}}]}`,
+		`~data: {"id":"c1","model":"m1","choices":[{"index":0,"delta":{},"finish_reason":"stop"}],"usage":{"prompt_tokens":5,"completion_tokens":20}}`,
+		`data: [DONE]`,
+	}
+	pacedResponses = []string{
+		"event: response.created\ndata: " + `{"type":"response.created","response":{"id":"r1","status":"in_progress","output":[]}}`,
+		"~event: response.reasoning_summary_text.delta\ndata: " + `{"type":"response.reasoning_summary_text.delta","item_id":"rs_1","output_index":0,"summary_index":0,"delta":"hmm"}`,
+		"~event: response.output_text.delta\ndata: " + `{"type":"response.output_text.delta","item_id":"msg_1","output_index":1,"content_index":0,"delta":"hi"}`,
+		"~event: response.completed\ndata: " + `{"type":"response.completed","response":{"id":"r1","status":"completed","output":[],"usage":{"input_tokens":5,"output_tokens":20}}}`,
+	}
+)
+
+const pacedGap = 80 * time.Millisecond
+
+func lastUsage(t *testing.T) usage.Record {
+	t.Helper()
+	recs := usage.Load(time.Time{})
+	if len(recs) == 0 {
+		t.Fatal("no usage recorded")
+	}
+	return recs[len(recs)-1]
+}
+
+// A streamed reply's first content (reasoning here) and first text are
+// timed from the request, whatever the vendor speaks and the agent asked
+// in, and kept in the usage, the request's route and its try.
+func TestUsageKeepsTimeToFirstToken(t *testing.T) {
+	gap := pacedGap.Milliseconds()
+	for _, c := range []struct {
+		name   string
+		proto  provider.Protocol
+		events []string
+		path   string
+		body   string
+	}{
+		{"anthropic", provider.Anthropic, pacedAnthropic, "/v1/messages", `{"model":"fake/m1","stream":true,"max_tokens":100,"messages":[{"role":"user","content":"hi"}]}`},
+		{"chat", provider.Chat, pacedChat, "/v1/chat/completions", `{"model":"fake/m1","stream":true,"messages":[{"role":"user","content":"hi"}]}`},
+		{"responses", provider.Responses, pacedResponses, "/v1/responses", `{"model":"fake/m1","stream":true,"input":"hi"}`},
+		// translated: the agent's Chat stream from the vendor's Anthropic one
+		{"chat from anthropic", provider.Anthropic, pacedAnthropic, "/v1/chat/completions", `{"model":"fake/m1","stream":true,"messages":[{"role":"user","content":"hi"}]}`},
+		// and its Responses stream from the vendor's Chat one
+		{"responses from chat", provider.Chat, pacedChat, "/v1/responses", `{"model":"fake/m1","stream":true,"input":"hi"}`},
+	} {
+		t.Run(c.name, func(t *testing.T) {
+			fresh(t)
+			up := httptest.NewServer(&paced{events: c.events, gap: pacedGap})
+			t.Cleanup(up.Close)
+			p := provider.Provider{ID: "fake", Name: "Fake", Key: "k", Models: []string{"m1"}}
+			switch c.proto {
+			case provider.Chat:
+				p.Chat = up.URL + "/v1"
+			case provider.Responses:
+				p.Responses = up.URL + "/v1"
+			case provider.Anthropic:
+				p.Anthropic = up.URL
+			}
+			if err := provider.Save(p); err != nil {
+				t.Fatal(err)
+			}
+			s := New()
+			rec := httptest.NewRecorder()
+			s.Handler().ServeHTTP(rec, httptest.NewRequest("POST", c.path, strings.NewReader(c.body)))
+			if rec.Code != 200 || !strings.Contains(rec.Body.String(), "hi") {
+				t.Fatalf("%d %s", rec.Code, rec.Body)
+			}
+			u := lastUsage(t)
+			if u.TTFT < gap || u.FirstText < 2*gap || u.FirstText-u.TTFT < gap/2 || u.Millis < u.FirstText+gap/2 || u.Output != 20 {
+				t.Errorf("usage ttft %d, first text %d, ms %d, out %d; want the reasoning after %d ms and the text after %d", u.TTFT, u.FirstText, u.Millis, u.Output, gap, 2*gap)
+			}
+			r := lastRoute(s)
+			if len(r.Tries) != 1 || r.TTFT != u.TTFT || r.FirstText != u.FirstText || r.Output != 20 ||
+				r.Tries[0].TTFT < gap || r.Tries[0].TTFT > u.TTFT || r.Tries[0].FirstText < 2*gap {
+				t.Errorf("route ttft %d/%d out %d, tries %+v", r.TTFT, r.FirstText, r.Output, r.Tries)
+			}
+			if calls := s.Recent(); len(calls) == 0 || calls[0].TTFT != u.TTFT {
+				t.Errorf("request log: %+v", calls)
+			}
+		})
+	}
+}
+
+// A reply that isn't streamed has no first token to time.
+func TestUsageLeavesTTFTOfAWholeReply(t *testing.T) {
+	fresh(t)
+	serveOn(t, "a", "ka", []string{"m"}, &keyed{})
+	s := New()
+	if code, body := postAs(t, s, "", `{"model":"a/m","messages":[{"role":"user","content":"hi"}]}`); code != 200 {
+		t.Fatalf("%d %s", code, body)
+	}
+	if u := lastUsage(t); u.TTFT != 0 || u.FirstText != 0 || u.Output != 5 {
+		t.Errorf("usage %+v", u)
+	}
+	if r := lastRoute(s); r.TTFT != 0 || r.Tries[0].TTFT != 0 {
+		t.Errorf("route %+v", r)
+	}
+}
+
+// In a group that fails over, each try keeps its own time to its first
+// token, from when it was sent, and the usage the request's, from when it
+// came: the time the failed try took is in it, as it is in ms.
+func TestGroupFailoverTimesEachTry(t *testing.T) {
+	fresh(t)
+	serveOn(t, "a", "ka", []string{"m"}, &paced{fail: 429, gap: pacedGap})
+	serveOn(t, "b", "kb", []string{"m"}, &paced{events: pacedChat, gap: pacedGap})
+	if err := provider.SaveGroup(provider.Group{Name: "Mine", Members: []string{"a/m", "b/m"}, Routing: provider.Ordered}); err != nil {
+		t.Fatal(err)
+	}
+	s := New()
+	code, body := postAs(t, s, "", `{"model":"group/mine","stream":true,"messages":[{"role":"user","content":"hi"}]}`)
+	if code != 200 || !strings.Contains(body, `"hi"`) {
+		t.Fatalf("%d %s", code, body)
+	}
+	r := lastRoute(s)
+	if len(r.Tries) != 2 || r.Tries[0].Status != 429 || r.Tries[1].Status != 200 {
+		t.Fatalf("tries %+v", r.Tries)
+	}
+	gap := pacedGap.Milliseconds()
+	failed, answered := r.Tries[0], r.Tries[1]
+	if failed.TTFT != 0 || failed.FirstText != 0 {
+		t.Errorf("the failed try timed: %+v", failed)
+	}
+	if answered.TTFT < gap || answered.FirstText < 2*gap || answered.TTFT >= answered.FirstText {
+		t.Errorf("the answering try: %+v", answered)
+	}
+	u := lastUsage(t)
+	if u.Provider != "b" || u.TTFT < answered.TTFT+failed.Millis || u.FirstText < answered.FirstText+failed.Millis || u.Millis <= u.FirstText {
+		t.Errorf("usage %+v; tries %+v", u, r.Tries)
+	}
+}
+
+// What counts as a reply's first content and first text, in each protocol,
+// its events split across writes as they come.
+func TestFirstTokenKinds(t *testing.T) {
+	for _, c := range []struct {
+		ev            string
+		content, text bool
+	}{
+		{`data: {"type":"content_block_start","index":0,"content_block":{"type":"tool_use","id":"t","name":"ls","input":{}}}`, true, false},
+		{`data: {"type":"content_block_start","index":0,"content_block":{"type":"text","text":""}}`, false, false},
+		{`data: {"type":"content_block_delta","index":0,"delta":{"type":"input_json_delta","partial_json":"{\"a"}}`, true, false},
+		{`data: {"type":"content_block_delta","index":0,"delta":{"type":"signature_delta","signature":"x"}}`, false, false},
+		{`data: {"type":"message_delta","delta":{"stop_reason":"end_turn"}}`, false, false},
+		{`data: {"choices":[{"delta":{"role":"assistant","content":null}}]}`, false, false},
+		{`data: {"choices":[{"delta":{"tool_calls":[{"index":0,"function":{"name":"ls"}}]}}]}`, true, false},
+		{`data: {"choices":[{"delta":{"reasoning":"hm"}}]}`, true, false},
+		{`data: {"choices":[{"delta":{"content":"hi"}}]}`, true, true},
+		{"event: response.function_call_arguments.delta\ndata: {\"delta\":\"{\"}", true, false},
+		{`data: {"type":"response.output_item.added","item":{"type":"function_call","name":"ls"}}`, true, false},
+		{`data: {"type":"response.output_item.added","item":{"type":"message"}}`, false, false},
+		{`data: {"type":"response.output_text.delta","delta":""}`, false, false},
+		{`data: {"candidates":[{"content":{"parts":[{"text":"hm","thought":true}]}}]}`, true, false},
+		{`data: {"candidates":[{"content":{"parts":[{"functionCall":{"name":"ls"}}]}}]}`, true, false},
+		{`data: {"candidates":[{"content":{"parts":[{"text":"hi"}]}}]}`, true, true},
+		{`: keep-alive`, false, false},
+		{`data: [DONE]`, false, false},
+	} {
+		content, text := firstKind([]byte(c.ev))
+		if content != c.content || text != c.text {
+			t.Errorf("%s: content %v text %v", c.ev, content, text)
+		}
+	}
+
+	// split across writes, \r\n-ended
+	f := firstToken{start: time.Now().Add(-time.Second)}
+	stream := "data: {\"choices\":[{\"delta\":{\"role\":\"assistant\"}}]}\r\n\r\ndata: {\"choices\":[{\"delta\":{\"tool_calls\":[{\"index\":0}]}}]}\r\n\r\ndata: {\"choices\":[{\"delta\":{\"content\":\"hi\"}}]}\r\n\r\n"
+	for i := 0; i < len(stream); i += 7 {
+		f.see([]byte(stream[i:min(i+7, len(stream))]))
+	}
+	if first, text := f.ms(); first < 1000 || text < first || !f.off || f.pend != nil {
+		t.Errorf("split: %d %d %+v", first, text, f)
+	}
+	// a JSON reply is not read
+	j := firstToken{start: time.Now()}
+	j.see([]byte(`{"choices":[{"message":{"content":"hi"}}]}` + "\n\n"))
+	if first, _ := j.ms(); first != 0 || !j.off {
+		t.Errorf("json: %+v", j)
+	}
+}
+
+// Codex's own models, relayed to the ChatGPT backend as they came, are
+// timed too — its stream says no Content-Type.
+func TestCodexBackendTimesFirstToken(t *testing.T) {
+	setup(t, provider.Chat, &fake{t: t})
+	p := &paced{events: pacedResponses, gap: pacedGap}
+	chatgpt(t, func(w http.ResponseWriter, r *http.Request) {
+		w.Header()["Content-Type"] = nil
+		p.ServeHTTP(w, r)
+	})
+	if code, body := codexPost(t, `{"model":"gpt-5.5","stream":true,"input":"hi"}`); code != 200 {
+		t.Fatalf("%d %s", code, body)
+	}
+	gap := pacedGap.Milliseconds()
+	if u := lastUsage(t); u.TTFT < gap || u.FirstText < 2*gap || u.Millis <= u.FirstText || u.Output != 20 {
+		t.Errorf("usage %+v", u)
+	}
+}

internal/gui/assets/app.js

@@ -2111,7 +2111,7 @@ function renderActivity() {
     r.append(el("span", "m", c.model));
     r.append(el("span", "p", c.from === c.to ? c.from : `${c.from} → ${c.to}`));
     r.append(el("span", "grow"));
-    r.append(el("span", "st", c.error ? `${c.status} ${c.error}` : `${c.status} · ${c.ms} ms`));
+    r.append(el("span", "st", c.error ? `${c.status} ${c.error}` : `${c.status} · ${c.ms} ms` + (c.ttft ? " · " + t("TTFT {ms}", { ms: `${c.ttft} ms` }) : "")));
     r.title = open ? t("Hide request and response bodies") : t("Show request and response bodies");
     const toggle = () => {
       if (expandedCalls.has(id)) expandedCalls.delete(id); else expandedCalls.add(id);
@@ -5103,6 +5103,13 @@ function renderUsage() {
       if (g.sub) sub.push(g.sub);
       sub.push(t(g.calls === 1 ? "{n} call" : "{n} calls", { n: g.calls }));
       if (g.errors) sub.push(t("{n} failed", { n: g.errors }));
+      // how long the streamed replies took to begin, and how fast they
+      // wrote after (#196)
+      if (g.timed) {
+        const ms = Math.round(g.ttft_ms / g.timed);
+        sub.push(t("TTFT {ms}", { ms: ms < 1000 ? t("{n} ms", { n: ms }) : t("{n} s", { n: (ms / 1000).toFixed(1) }) }));
+        if (g.decode_ms > 0) sub.push(t("{n} tok/s", { n: Math.round(g.decode_out / (g.decode_ms / 1000)) }));
+      }
       who.append(el("div", "sub", sub.join(" · ")));
       r.append(who);
       const share = el("div", "share");

internal/gui/assets/i18n.js

@@ -1122,6 +1122,10 @@ const I18N = {
     "{n} on": "启用 {n} 个",
     "{n} s": "{n} 秒",
     "{n} ms": "{n} 毫秒",
+    "TTFT {ms}": "首字 {ms}",
+    "first token in {ms}": "{ms} 后出首个 token",
+    "first text in {ms}": "{ms} 后出首字",
+    "{n} tok/s": "{n} token/秒",
     "{n} min": "{n} 分钟",
     "{h} h {m} min": "{h} 小时 {m} 分钟",
     "{n} h": "{n} 小时",

internal/gui/assets/routing.js

@@ -127,6 +127,16 @@
     const hm = d.toLocaleTimeString([], { hour: "2-digit", minute: "2-digit" });
     return d.toDateString() === n.toDateString() ? hm : d.toLocaleDateString([], { weekday: "short" }) + " " + hm;
   }
+  // how long a reply took to begin, and how fast it wrote after (#196)
+  const speedOf = (out, ms, ttft) => out && ttft && ms > ttft ? out / ((ms - ttft) / 1000) : 0;
+  function firstNote(r, tr) {
+    if (!tr.ttft) return "";
+    let s = " · " + t("first token in {ms}", { ms: took(tr.ttft) });
+    if (tr.firstText > tr.ttft) s += " · " + t("first text in {ms}", { ms: took(tr.firstText) });
+    const v = speedOf(r.out, tr.ms, tr.ttft);
+    if (v) s += " · " + t("{n} tok/s", { n: Math.round(v) });
+    return s;
+  }
   const tokens = (n) => n >= 1e6 ? (n / 1e6).toFixed(1) + "M" : n >= 1e3 ? (n / 1e3).toFixed(1) + "k" : String(Math.round(n));
   const pct = (n) => Math.round(n) + "%";
   const FAIL = { rate: "rate limited", credit: "out of credit", quota: "quota used up", other: "failed", canceled: "canceled", foreign: "another account's reasoning", floor: "reply too short", verify: "needs verification" };
@@ -429,7 +439,7 @@
     if (tr.effort) name += " " + t("at {level} reasoning", { level: tr.effort });
     if (!tr.done) return t("{who} is answering…", { who: name });
     if (tr.status < 400) {
-      const tk = r.tokens ? " · " + t("{n} tokens", { n: tokens(r.tokens) }) : "";
+      const tk = (r.tokens ? " · " + t("{n} tokens", { n: tokens(r.tokens) }) : "") + firstNote(r, tr);
       return i > 0
         ? t("{who} answered in {ms}{tk}. {agent} got one clean reply and never saw the {n} that failed first.", { who: name, ms: took(tr.ms), tk, agent, n: i })
         : t("{who} answered in {ms}{tk}.", { who: name, ms: took(tr.ms), tk });
@@ -1024,6 +1034,7 @@
       const meta = [];
       if (r.tries.length > 1) meta.push(t("{n} tries", { n: r.tries.length }));
       if (r.done && r.ms) meta.push(took(r.ms));
+      if (r.done && r.ttft) meta.push(t("TTFT {ms}", { ms: took(r.ttft) }));
       if (r.tokens) meta.push(t("{n} tokens", { n: tokens(r.tokens) }));
       b.append(when, asked, to, el("span", "meta", meta.join(" · ")));
       b.title = `${agentName(r.agent)} · ${r.model} → ${r.provider}`;

internal/usage/usage.go

@@ -36,7 +36,13 @@ type Record struct {
 	// pick for the turn, or the agent's own — as it takes it; "" for none
 	Effort string `json:"effort,omitempty"`
 	Millis int64  `json:"ms"`
-	Status int    `json:"status"`
+	// TTFT: ms from the request to its reply's first content — text,
+	// reasoning or a tool call — and FirstText to its first text, counted
+	// as Millis is, so Millis-TTFT is how long the reply took to write;
+	// none for a reply that wasn't streamed (#196)
+	TTFT      int64 `json:"ttft_ms,omitempty"`
+	FirstText int64 `json:"first_text_ms,omitempty"`
+	Status    int   `json:"status"`
 	// Session is the conversation the call was part of, as its agent names
 	// it (X-Magpie-Session, or the session header Claude Code, Codex or
 	// OpenCode sends): several sessions on one model told apart
@@ -162,11 +168,36 @@ type Totals struct {
 	Reasoning  int     `json:"reasoning"`
 	Cost       float64 `json:"cost"`     // USD at list prices, for the priced calls
 	Unpriced   int     `json:"unpriced"` // calls with tokens but no known price
+	// Timed: the answered calls whose first token was timed (streamed),
+	// TTFT the sum of their ttft_ms; DecodeMs the time from it to the end
+	// of those that wrote any, over which DecodeOut tokens came: their
+	// mean wait, and how fast they wrote (#196)
+	Timed     int   `json:"timed,omitempty"`
+	TTFT      int64 `json:"ttft_ms,omitempty"`
+	DecodeMs  int64 `json:"decode_ms,omitempty"`
+	DecodeOut int   `json:"decode_out,omitempty"`
 }
 
 // Tokens is what went in and out, excluding cache traffic.
 func (t Totals) Tokens() int { return t.Input + t.Output }
 
+// MeanTTFT is the mean ms to the first token of the timed calls, 0 for none.
+func (t Totals) MeanTTFT() int64 {
+	if t.Timed == 0 {
+		return 0
+	}
+	return t.TTFT / int64(t.Timed)
+}
+
+// Speed is how fast the timed calls wrote, in tokens a second after their
+// first: 0 for none.
+func (t Totals) Speed() float64 {
+	if t.DecodeMs <= 0 {
+		return 0
+	}
+	return float64(t.DecodeOut) / (float64(t.DecodeMs) / 1000)
+}
+
 func (t *Totals) add(r Record, price *catalog.Price) {
 	t.Calls++
 	if r.Status >= 400 {
@@ -177,6 +208,14 @@ func (t *Totals) add(r Record, price *catalog.Price) {
 	t.CacheRead += r.CacheRead
 	t.CacheWrite += r.CacheWrite
 	t.Reasoning += r.Reasoning
+	if r.TTFT > 0 && r.Status < 400 {
+		t.Timed++
+		t.TTFT += r.TTFT
+		if r.Output > 0 && r.Millis > r.TTFT {
+			t.DecodeMs += r.Millis - r.TTFT
+			t.DecodeOut += r.Output
+		}
+	}
 	if r.Input+r.Output == 0 {
 		return
 	}

internal/usage/usage_test.go

@@ -1,7 +1,9 @@
 package usage
 
 import (
+	"encoding/json"
 	"path/filepath"
+	"strings"
 	"testing"
 	"time"
 
@@ -101,3 +103,32 @@ func TestSummarizeSessions(t *testing.T) {
 		t.Fatalf("%+v", ss)
 	}
 }
+
+// The timed calls (#196) sum to a mean time to the first token and how
+// fast the replies were written after it; old records, whole replies and
+// failures aren't in them, and a record without them reads as before.
+func TestSummarizeTimesFirstTokens(t *testing.T) {
+	now := time.Date(2026, 9, 23, 15, 30, 0, 0, time.UTC)
+	at := now.Add(-time.Hour)
+	recs := []Record{
+		{Time: at, Provider: "p", Model: "m", Output: 100, Millis: 3000, TTFT: 1000, FirstText: 2000, Status: 200},
+		{Time: at, Provider: "p", Model: "m", Output: 50, Millis: 1500, TTFT: 500, Status: 200},
+		{Time: at, Provider: "p", Model: "m", Output: 999, Millis: 800, Status: 200}, // not streamed
+		{Time: at, Provider: "p", Model: "m", Millis: 100, TTFT: 90, Status: 502},    // failed
+	}
+	s := summarize(Today, now, recs)
+	m := s.Models[0]
+	if m.Timed != 2 || m.MeanTTFT() != 750 || m.DecodeMs != 3000 || m.DecodeOut != 150 || m.Speed() != 50 {
+		t.Fatalf("model: %+v", m.Totals)
+	}
+	if s.Timed != 2 || s.Series[14].Timed != 2 {
+		t.Fatalf("totals: %+v", s.Totals)
+	}
+	if (Totals{}).Speed() != 0 || (Totals{}).MeanTTFT() != 0 {
+		t.Fatal("nothing timed")
+	}
+	b, _ := json.Marshal(Record{Time: at, Provider: "p", Model: "m", Millis: 5})
+	if strings.Contains(string(b), "ttft") || strings.Contains(string(b), "first_text") {
+		t.Fatalf("untimed record: %s", b)
+	}
+}

usage_cli.go

@@ -58,7 +58,7 @@ func usageCmd(args []string) error {
 			if s.Tokens() > 0 {
 				share = fmt.Sprintf("%3.0f%%", 100*float64(g.Tokens())/float64(s.Tokens()))
 			}
-			fmt.Println("  "+pad(name(g), w), muted.Render(share), pad(fmtTokens(g.Tokens()), 7), faint.Render(pad(plural(g.Calls, "call"), 10)), cost(g.Totals))
+			fmt.Println("  "+pad(name(g), w), muted.Render(share), pad(fmtTokens(g.Tokens()), 7), faint.Render(pad(plural(g.Calls, "call"), 10)), cost(g.Totals), faint.Render(speed(g.Totals)))
 		}
 	}
 	table("agents", s.Agents, func(g stats.Group) string {
@@ -86,6 +86,26 @@ func usageCmd(args []string) error {
 	return nil
 }
 
+// speed is how long the timed calls took to their first token, and how
+// fast they wrote after it (#196); "" when none was timed.
+func speed(t stats.Totals) string {
+	if t.Timed == 0 {
+		return ""
+	}
+	out := "ttft " + fmtMs(t.MeanTTFT())
+	if v := t.Speed(); v > 0 {
+		out += fmt.Sprintf(" · %.0f tok/s", v)
+	}
+	return out
+}
+
+func fmtMs(ms int64) string {
+	if ms < 1000 {
+		return fmt.Sprintf("%d ms", ms)
+	}
+	return fmt.Sprintf("%.1f s", float64(ms)/1000)
+}
+
 func plural(n int, unit string) string {
 	if n == 1 {
 		return "1 " + unit