From d924802de5b4f2fbc577c2c2b490c70200fbd9fa Mon Sep 17 00:00:00 2001 From: yetone Date: Tue, 29 Sep 2026 16:32:08 +0800 Subject: [PATCH] =?UTF-8?q?usage:=20a=20streamed=20reply's=20time=20to=20i?= =?UTF-8?q?ts=20first=20token=20is=20kept,=20and=20its=20first=20text's=20?= =?UTF-8?q?(#196:=20usage=20=E8=AE=B0=E5=BD=95=E9=A6=96=E5=AD=97=E5=BB=B6?= =?UTF-8?q?=E8=BF=9F=EF=BC=88TTFT=EF=BC=89=EF=BC=8C=E7=94=A8=E4=BA=8E?= =?UTF-8?q?=E8=AE=A1=E7=AE=97=E6=A8=A1=E5=9E=8B=E7=9A=84=E7=9C=9F=E5=AE=9E?= =?UTF-8?q?=E7=94=9F=E6=88=90=E9=80=9F=E5=BA=A6)=20=E2=80=94=20usage.jsonl?= =?UTF-8?q?=20had=20only=20a=20call's=20whole=20ms=20and=20its=20out=20tok?= =?UTF-8?q?ens,=20so=20how=20fast=20a=20model=20writes=20couldn't=20be=20t?= =?UTF-8?q?old=20from=20how=20long=20it=20waited=20or=20thought.=20The=20r?= =?UTF-8?q?eply=20is=20now=20read=20as=20it=20goes=20to=20the=20agent,=20i?= =?UTF-8?q?n=20the=20agent's=20protocol=20whatever=20the=20vendor=20spoke?= =?UTF-8?q?=20(Anthropic=20content=5Fblock=5Fdelta=20text/thinking/input?= =?UTF-8?q?=5Fjson=20and=20a=20tool=5Fuse's=20start,=20Chat=20content/reas?= =?UTF-8?q?oning=5Fcontent/reasoning/tool=5Fcalls,=20Responses=20output=5F?= =?UTF-8?q?text/reasoning/function=5Fcall=5Farguments=20deltas=20and=20a?= =?UTF-8?q?=20function=20call's=20start,=20Gemini=20parts),=20and=20each?= =?UTF-8?q?=20record=20gets=20ttft=5Fms=20to=20the=20first=20content=20and?= =?UTF-8?q?=20first=5Ftext=5Fms=20to=20the=20first=20text,=20counted=20fro?= =?UTF-8?q?m=20the=20request=20as=20ms=20is,=20so=20ms=20=E2=88=92=20ttft?= =?UTF-8?q?=5Fms=20is=20the=20writing=20time;=20a=20reply=20that=20isn't?= =?UTF-8?q?=20streamed=20gets=20neither,=20and=20omitempty=20leaves=20old?= =?UTF-8?q?=20records=20as=20they=20were.=20Only=20the=20stream's=20events?= =?UTF-8?q?=20up=20to=20its=20first=20text=20are=20read=20(a=20JSON=20repl?= =?UTF-8?q?y,=20or=20past=208=20MB,=20not=20at=20all).=20Each=20try=20in?= =?UTF-8?q?=20the=20routing=20trace=20keeps=20its=20own=20from=20when=20it?= =?UTF-8?q?=20was=20sent,=20so=20a=20group=20that=20fails=20over=20shows?= =?UTF-8?q?=20which=20member=20was=20slow,=20and=20the=20route,=20the=20re?= =?UTF-8?q?quest=20log=20and=20the=20Codex=20backend's=20relay=20keep=20th?= =?UTF-8?q?em=20too.=20Shown=20on=20the=20Routing=20page=20(TTFT=20in=20th?= =?UTF-8?q?e=20list,=20first=20token=20/=20first=20text=20/=20tok/s=20in?= =?UTF-8?q?=20a=20try's=20story),=20in=20the=20Gateway's=20request=20log,?= =?UTF-8?q?=20and=20on=20the=20Usage=20page=20and=20in=20`magpie=20usage`?= =?UTF-8?q?=20per=20model=20as=20the=20mean=20TTFT=20and=20tok/s=20=3D=20o?= =?UTF-8?q?ut=20=C3=B7=20(ms=20=E2=88=92=20ttft)=20over=20the=20answered?= =?UTF-8?q?=20streamed=20calls.=20Tested=20with=20fake=20vendors=20streami?= =?UTF-8?q?ng=20a=20gap=20apart=20for=20Anthropic,=20Chat=20and=20Response?= =?UTF-8?q?s,=20as=20they=20came=20and=20translated=20(Chat=20from=20Anthr?= =?UTF-8?q?opic,=20Responses=20from=20Chat),=20the=20ChatGPT=20backend=20w?= =?UTF-8?q?ithout=20a=20Content-Type,=20a=20whole=20reply,=20a=20group=20w?= =?UTF-8?q?hose=20first=20member=20fails=20(its=20try=20untimed,=20the=20s?= =?UTF-8?q?econd's=20timed=20from=20its=20own=20start,=20the=20request's?= =?UTF-8?q?=20including=20the=20failed=20try),=20each=20protocol's=20event?= =?UTF-8?q?s=20and=20split=20writes,=20and=20the=20summary's=20sums;=20the?= =?UTF-8?q?=20GUI's=20browser=20tests=20pass?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- internal/gateway/codex_backend.go | 20 ++- internal/gateway/fallback.go | 5 +- internal/gateway/gateway.go | 52 ++++-- internal/gateway/trace.go | 18 ++- internal/gateway/ttft.go | 198 +++++++++++++++++++++++ internal/gateway/ttft_test.go | 257 ++++++++++++++++++++++++++++++ internal/gui/assets/app.js | 9 +- internal/gui/assets/i18n.js | 4 + internal/gui/assets/routing.js | 13 +- internal/usage/usage.go | 41 ++++- internal/usage/usage_test.go | 31 ++++ usage_cli.go | 22 ++- 12 files changed, 638 insertions(+), 32 deletions(-) create mode 100644 internal/gateway/ttft.go create mode 100644 internal/gateway/ttft_test.go diff --git a/internal/gateway/codex_backend.go b/internal/gateway/codex_backend.go index 19d682e9..fbee8fae 100644 --- a/internal/gateway/codex_backend.go +++ b/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 diff --git a/internal/gateway/fallback.go b/internal/gateway/fallback.go index 0dca27a2..694954ed 100644 --- a/internal/gateway/fallback.go +++ b/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) } diff --git a/internal/gateway/gateway.go b/internal/gateway/gateway.go index 00a6b841..c901c2c0 100644 --- a/internal/gateway/gateway.go +++ 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) { diff --git a/internal/gateway/trace.go b/internal/gateway/trace.go index 605e41b5..ad29bdbe 100644 --- a/internal/gateway/trace.go +++ b/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 { diff --git a/internal/gateway/ttft.go b/internal/gateway/ttft.go new file mode 100644 index 00000000..985ee70f --- /dev/null +++ b/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 +} diff --git a/internal/gateway/ttft_test.go b/internal/gateway/ttft_test.go new file mode 100644 index 00000000..ce07ace0 --- /dev/null +++ b/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) + } +} diff --git a/internal/gui/assets/app.js b/internal/gui/assets/app.js index 5fa6151d..1977493d 100644 --- a/internal/gui/assets/app.js +++ b/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"); diff --git a/internal/gui/assets/i18n.js b/internal/gui/assets/i18n.js index 89ecfa08..18fb5c33 100644 --- a/internal/gui/assets/i18n.js +++ b/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} 小时", diff --git a/internal/gui/assets/routing.js b/internal/gui/assets/routing.js index 07157760..fd1f8a49 100644 --- a/internal/gui/assets/routing.js +++ b/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}`; diff --git a/internal/usage/usage.go b/internal/usage/usage.go index f27d22ed..64d53dc4 100644 --- a/internal/usage/usage.go +++ b/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 } diff --git a/internal/usage/usage_test.go b/internal/usage/usage_test.go index 368ae1e3..ff0f7956 100644 --- a/internal/usage/usage_test.go +++ b/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) + } +} diff --git a/usage_cli.go b/usage_cli.go index ddd7887c..9754af85 100644 --- a/usage_cli.go +++ 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