think-meter

1// think-meter: the terminal's turn timer, for the desktop app, broken down.
2//
3// How it measures (see README for the caveats):
4//   * every model request streams through `turn.step`; the mod timestamps the
5//     first streamed event, the first visible output (text or a tool call),
6//     and the end of the stream
7//   * "for"      = the turn's wall-clock length, prompt submitted -> answer
8//                  complete (the terminal's "Cooked for", Codex's "Worked for")
9//   * "waiting"  = request sent -> first streamed event
10//   * "thinking" = first streamed event -> first visible output
11//   * "writing"  = first visible output -> end of stream
12//   * "tools"    = wall-clock time the main loop's tool calls ran
13//   * "other"    = whatever is left of the turn (in /think-stats only)
14//   * "tok/s"    = output tokens (thinking included) / streaming time
15//   * a turn's numbers are the sum over its requests; subagents are left out
16
17import {
18  addStep,
19  coveredMs,
20  emptyTurn,
21  finishStep,
22  finishTurn,
23  formatSessionSummary,
24  formatTurnLine,
25  isVisibleKind,
26  lineForBlock,
27  liveSuffix,
28  newStepTimes,
29  turnWord,
30  withLine,
31  type StepStats,
32  type TurnStats,
33} from './meter.ts'
34
35/** Keep memory bounded in very long sessions. */
36const MAX_HISTORY = 2000
37
38/** Finished turns and requests of the main conversation, for /think-stats. */
39let finishedTurns: TurnStats[] = []
40let finishedSteps: StepStats[] = []
41
42/** Running totals of turns still in progress, by turn id. */
43const openTurns = new Map<string, TurnStats>()
44/** When each main-loop tool call of a turn in progress ran, by turn id. */
45const openToolRuns = new Map<string, Array<[number, number]>>()
46/** The main conversation's turn in progress; tool calls carry no turn id of their own. */
47let mainTurnId: string | null = null
48/** The line under each finished answer, by the answer's text, oldest first. */
49const linesByAnswer = new Map<string, string>()
50
51/** When the main conversation's current request entered its thinking phase. */
52let liveThinkStart: number | null = null
53/** The timer that redraws the spinner while thinking. */
54let liveTimer: { cancel: () => void } | null = null
55
56function stopLiveTimer(): void {
57  if (liveTimer !== null) liveTimer.cancel()
58  liveTimer = null
59  liveThinkStart = null
60}
61
62function remember<T>(list: T[], item: T): T[] {
63  const next = [...list, item]
64  return next.length > MAX_HISTORY ? next.slice(next.length - MAX_HISTORY) : next
65}
66
67export function register(on: any, options: any) {
68  const showTurnLine = options?.showTurnLine !== false
69  const liveSpinner = options?.liveSpinner !== false
70
71  // A reload starts from a clean slate.
72  finishedTurns = []
73  finishedSteps = []
74  openTurns.clear()
75  openToolRuns.clear()
76  linesByAnswer.clear()
77  mainTurnId = null
78  stopLiveTimer()
79
80  on('session.start', async ($: any, e: any, next: any) => {
81    await $.command.register({
82      name: 'think-stats',
83      description: 'Show thinking time and output speed for this session',
84    })
85    return next(e)
86  })
87
88  on('command.run', { command: 'think-stats' }, async () => {
89    return { text: formatSessionSummary(finishedTurns, finishedSteps) }
90  })
91
92  on('turn.step', async function* ($: any, e: any, next: any) {
93    const isMain = !e.agentId
94    if (isMain) mainTurnId = e.turnId
95    const times = newStepTimes(await $.clock.now())
96    const stream = next(e)
97    try {
98      for await (const chunk of stream) {
99        if (times.firstChunkAt === null) {
100          times.firstChunkAt = await $.clock.now()
101          if (isMain && liveSpinner) {
102            stopLiveTimer()
103            liveThinkStart = times.firstChunkAt
104            liveTimer = $.clock.every(500, () => $.ui.invalidate('ui.render'))
105          }
106        }
107        if (chunk.kind === 'thinking' && chunk.text) times.sawThinkingText = true
108        if (times.firstVisibleAt === null && isVisibleKind(chunk.kind)) {
109          times.firstVisibleAt = await $.clock.now()
110          if (isMain && liveThinkStart !== null) {
111            stopLiveTimer()
112            $.ui.invalidate('ui.render')
113          }
114        }
115        yield chunk
116      }
117    } finally {
118      if (isMain && liveThinkStart !== null) {
119        stopLiveTimer()
120        $.ui.invalidate('ui.render')
121      }
122    }
123
124    const result = await stream.result
125    times.endedAt = await $.clock.now()
126
127    if (isMain && result) {
128      const usage = result.usage
129      const step = finishStep(times, usage?.model ?? e.model, usage?.output_tokens ?? 0)
130      if (step !== null) {
131        finishedSteps = remember(finishedSteps, step)
132        openTurns.set(e.turnId, addStep(openTurns.get(e.turnId) ?? emptyTurn(), step))
133      }
134    }
135    return result
136  })
137
138  // Only the timing is recorded; the tool's arguments and result pass through untouched.
139  on('tool.call', async ($: any, e: any, next: any) => {
140    const turnId = mainTurnId
141    if (e.agentId || turnId === null) return next(e)
142    const startedAt = await $.clock.now()
143    try {
144      return await next(e)
145    } finally {
146      const runs = openToolRuns.get(turnId) ?? []
147      runs.push([startedAt, await $.clock.now()])
148      openToolRuns.set(turnId, runs)
149    }
150  })
151
152  on('ui.render', { component: 'Spinner' }, async ($: any, e: any, next: any) => {
153    if (liveThinkStart === null) return next(e)
154    const now = await $.clock.now()
155    return next({ ...e, props: { ...e.props, suffix: liveSuffix(liveThinkStart, now) } })
156  })
157
158  on('turn.complete', async ($: any, e: any, next: any) => {
159    const result = await next(e)
160    if (e.agentId) return result
161
162    const measured = openTurns.get(e.turnId)
163    const toolRuns = openToolRuns.get(e.turnId) ?? []
164    openTurns.delete(e.turnId)
165    openToolRuns.delete(e.turnId)
166    if (mainTurnId === e.turnId) mainTurnId = null
167    stopLiveTimer()
168    if (measured === undefined || measured.requests === 0) return result
169
170    const turn = finishTurn(measured, e.durationMs, coveredMs(toolRuns))
171    finishedTurns = remember(finishedTurns, turn)
172    if (!showTurnLine) return result
173
174    // The line is drawn under the answer by the AssistantMessage hook below, not
175    // returned here: the desktop app folds a turn.complete line into a notice
176    // the person has to click open.
177    const answer = typeof e.answer === 'string' ? e.answer.trim() : ''
178    if (showTurnLine && answer !== '') {
179      linesByAnswer.delete(answer)
180      linesByAnswer.set(answer, formatTurnLine(turn, e.isAborted === true, turnWord(e.turnId)))
181      if (linesByAnswer.size > MAX_HISTORY) linesByAnswer.delete(linesByAnswer.keys().next().value)
182      $.ui.invalidate('ui.render')
183    }
184    return result
185  })
186
187  // Only the drawing changes: the stored reply, and what the model reads, stay as they were.
188  on('ui.render', { component: 'AssistantMessage' }, async ($: any, e: any, next: any) => {
189    const line = typeof e.props?.text === 'string' ? lineForBlock(linesByAnswer, e.props.text) : undefined
190    if (line === undefined) return next(e)
191    return next({ ...e, props: { ...e.props, text: withLine(e.props.text, line) } })
192  })
193
194  on('session.end', async ($: any, e: any, next: any) => {
195    stopLiveTimer()
196    return next(e)
197  })
198}
199

1// Pure timing and formatting logic for think-meter.
2// Nothing in this file touches the mods API, so it can be unit-tested directly.
3
4/** Chunk kinds that mean the model has started producing visible output. */
5const VISIBLE_KINDS = new Set(['text', 'tool', 'input'])
6
7/** Below this much streaming time, tokens/second is too noisy to report. */
8export const MIN_STREAM_MS_FOR_RATE = 500
9
10/** Timestamps (ms) collected while one model request streams. */
11export type StepTimes = {
12  /** When the request was handed on (before the first chunk). */
13  sentAt: number
14  /** When the first chunk of any kind arrived. */
15  firstChunkAt: number | null
16  /** When the first visible chunk (text or tool call) arrived. */
17  firstVisibleAt: number | null
18  /** When the stream finished. */
19  endedAt: number | null
20  /** Whether any thinking text streamed (false when thinking is hidden or absent). */
21  sawThinkingText: boolean
22}
23
24/** What one model request cost in time and tokens. */
25export type StepStats = {
26  model: string
27  /** Request sent -> first streamed event (queueing + prompt processing). */
28  ttftMs: number
29  /** First streamed event -> first visible output (about the thinking time). */
30  thinkMs: number
31  /** First streamed event -> end of stream. */
32  streamMs: number
33  outputTokens: number
34  sawThinkingText: boolean
35}
36
37/** Totals for one turn (one prompt and every request it took). */
38export type TurnStats = {
39  requests: number
40  /** Request sent -> first streamed event, summed over requests. */
41  waitMs: number
42  thinkMs: number
43  streamMs: number
44  /** Wall-clock time the main loop's tools ran; parallel calls are counted once. */
45  toolMs: number
46  /** Wall-clock length of the whole turn, prompt submitted -> answer complete (0 until it ends). */
47  totalMs: number
48  outputTokens: number
49  models: string[]
50  sawThinkingText: boolean
51}
52
53/** Where one turn's time went. The parts add up to totalMs. */
54export type TurnBreakdown = {
55  totalMs: number
56  waitMs: number
57  thinkMs: number
58  /** Streaming visible output: text and tool-call arguments. */
59  writeMs: number
60  toolMs: number
61  /** What no measured phase covers: hooks, retries, time between requests. */
62  otherMs: number
63}
64
65export function newStepTimes(sentAt: number): StepTimes {
66  return { sentAt, firstChunkAt: null, firstVisibleAt: null, endedAt: null, sawThinkingText: false }
67}
68
69/** True when this chunk kind is the first sign of visible output. */
70export function isVisibleKind(kind: string): boolean {
71  return VISIBLE_KINDS.has(kind)
72}
73
74/** Turns collected timestamps into step stats. Returns null if nothing streamed. */
75export function finishStep(times: StepTimes, model: string, outputTokens: number): StepStats | null {
76  if (times.firstChunkAt === null || times.endedAt === null) return null
77  const first = times.firstChunkAt
78  const end = Math.max(times.endedAt, first)
79  // A thinking-only response has no visible output: all of it counts as thinking.
80  const visible =
81    times.firstVisibleAt === null ? end : Math.min(Math.max(times.firstVisibleAt, first), end)
82  return {
83    model,
84    ttftMs: Math.max(0, first - times.sentAt),
85    thinkMs: visible - first,
86    streamMs: end - first,
87    outputTokens: Math.max(0, outputTokens || 0),
88    sawThinkingText: times.sawThinkingText,
89  }
90}
91
92export function emptyTurn(): TurnStats {
93  return {
94    requests: 0,
95    waitMs: 0,
96    thinkMs: 0,
97    streamMs: 0,
98    toolMs: 0,
99    totalMs: 0,
100    outputTokens: 0,
101    models: [],
102    sawThinkingText: false,
103  }
104}
105
106/** Adds one request's stats to a turn's totals, returning a new object. */
107export function addStep(turn: TurnStats, step: StepStats): TurnStats {
108  return {
109    ...turn,
110    requests: turn.requests + 1,
111    waitMs: turn.waitMs + step.ttftMs,
112    thinkMs: turn.thinkMs + step.thinkMs,
113    streamMs: turn.streamMs + step.streamMs,
114    outputTokens: turn.outputTokens + step.outputTokens,
115    models: turn.models.includes(step.model) ? turn.models : [...turn.models, step.model],
116    sawThinkingText: turn.sawThinkingText || step.sawThinkingText,
117  }
118}
119
120/** Wall-clock time covered by [start, end] intervals, overlapping parts counted once. */
121export function coveredMs(intervals: Array<[number, number]>): number {
122  const sorted = intervals.filter(([start, end]) => end > start).sort((a, b) => a[0] - b[0])
123  let total = 0
124  let runStart = 0
125  let runEnd = -Infinity
126  for (const [start, end] of sorted) {
127    if (start > runEnd) {
128      if (runEnd > runStart) total += runEnd - runStart
129      runStart = start
130      runEnd = end
131    } else {
132      runEnd = Math.max(runEnd, end)
133    }
134  }
135  if (runEnd > runStart) total += runEnd - runStart
136  return total
137}
138
139/** Records a finished turn's wall-clock length and tool time. */
140export function finishTurn(turn: TurnStats, totalMs: number, toolMs: number): TurnStats {
141  return { ...turn, totalMs: Math.max(0, totalMs || 0), toolMs: Math.max(0, toolMs || 0) }
142}
143
144/**
145 * Splits a turn into wait, thinking, writing, tools and other. When the
146 * reported total is shorter than the measured parts (clock skew), the parts win.
147 */
148export function breakdown(turn: TurnStats): TurnBreakdown {
149  const writeMs = Math.max(0, turn.streamMs - turn.thinkMs)
150  const measured = turn.waitMs + turn.thinkMs + writeMs + turn.toolMs
151  const totalMs = Math.max(turn.totalMs, measured)
152  return {
153    totalMs,
154    waitMs: turn.waitMs,
155    thinkMs: turn.thinkMs,
156    writeMs,
157    toolMs: turn.toolMs,
158    otherMs: totalMs - measured,
159  }
160}
161
162/** Output tokens per second, or null when the sample is too short to trust. */
163export function tokensPerSecond(outputTokens: number, streamMs: number): number | null {
164  if (streamMs < MIN_STREAM_MS_FOR_RATE || outputTokens <= 0) return null
165  return (outputTokens * 1000) / streamMs
166}
167
168/** 1234 -> "1,234". Avoids locale differences between machines. */
169export function formatCount(n: number): string {
170  return String(Math.round(n)).replace(/\B(?=(\d{3})+(?!\d))/g, ',')
171}
172
173/** The past-tense words Claude Code's terminal closes a turn with ("Cooked for 1m 6s"). */
174export const TURN_WORDS = ['Baked', 'Brewed', 'Churned', 'Cogitated', 'Cooked', 'Crunched', 'Sautéed', 'Worked']
175
176/** A word for this turn, the same every time the line is drawn. */
177export function turnWord(turnId: string): string {
178  let hash = 0
179  for (const ch of turnId) hash = (hash * 31 + ch.charCodeAt(0)) >>> 0
180  return TURN_WORDS[hash % TURN_WORDS.length]
181}
182
183/** Like the terminal's turn line: 3.9s, 55s, 1m 4s. */
184export function formatSpan(ms: number): string {
185  const safe = Math.max(0, ms)
186  const tenths = Math.round(safe / 100)
187  if (tenths < 100) return (tenths / 10).toFixed(1) + 's'
188  const seconds = Math.round(safe / 1000)
189  if (seconds < 60) return seconds + 's'
190  return Math.floor(seconds / 60) + 'm ' + (seconds % 60) + 's'
191}
192
193/** Parts shorter than this are left off the line. */
194export const MIN_PART_MS_TO_SHOW = 1000
195
196/** "thinking 4.0s · writing 21s · tools 16s · waiting 14s", parts under a second left out. */
197export function formatParts(b: TurnBreakdown, withOther: boolean): string {
198  const parts: Array<[string, number]> = [
199    ['thinking', b.thinkMs],
200    ['writing', b.writeMs],
201    ['tools', b.toolMs],
202    ['waiting', b.waitMs],
203  ]
204  if (withOther) parts.push(['other', b.otherMs])
205  return parts
206    .filter(([, ms]) => ms >= MIN_PART_MS_TO_SHOW)
207    .map(([name, ms]) => name + ' ' + formatSpan(ms))
208    .join(' · ')
209}
210
211/**
212 * The line shown under an answer: "Cooked for 55s · thinking 3.9s · 132 tok/s".
213 * Thinking under a second and a rate from too short a sample are left off;
214 * the full split is in /think-stats.
215 */
216export function formatTurnLine(turn: TurnStats, isAborted: boolean, word = 'Worked'): string {
217  const b = breakdown(turn)
218  const parts = [isAborted ? 'Interrupted after ' + formatSpan(b.totalMs) : word + ' for ' + formatSpan(b.totalMs)]
219  if (b.thinkMs >= MIN_PART_MS_TO_SHOW) parts.push('thinking ' + formatSpan(b.thinkMs))
220  const rate = tokensPerSecond(turn.outputTokens, turn.streamMs)
221  if (rate !== null) parts.push(rate.toFixed(0) + ' tok/s')
222  return parts.join(' · ')
223}
224
225/**
226 * The line for a drawn text block, if the block ends a finished answer.
227 * `lines` maps each answer's text to its line, oldest first; the newest match
228 * wins, so a short reply that repeats ("Done.") gets the latest turn's line.
229 */
230export function lineForBlock(lines: Map<string, string>, blockText: string): string | undefined {
231  const block = blockText.trim()
232  if (block === '') return undefined
233  const exact = lines.get(block)
234  if (exact !== undefined) return exact
235  let found: string | undefined
236  for (const [answer, line] of lines) if (answer.endsWith(block)) found = line
237  return found
238}
239
240/** The block's text with the line beneath it, set apart and in italics. */
241export function withLine(blockText: string, line: string): string {
242  return blockText.replace(/\s+$/, '') + '\n\n*' + line + '*'
243}
244
245/** "1 turn", "2 turns". */
246function count(n: number, noun: string): string {
247  return formatCount(n) + ' ' + noun + (n === 1 ? '' : 's')
248}
249
250/** Median of a list of numbers (0 for an empty list). */
251export function median(values: number[]): number {
252  if (values.length === 0) return 0
253  const sorted = [...values].sort((a, b) => a - b)
254  const mid = Math.floor(sorted.length / 2)
255  return sorted.length % 2 === 1 ? sorted[mid] : (sorted[mid - 1] + sorted[mid]) / 2
256}
257
258/** The text /think-stats prints for the session so far. */
259export function formatSessionSummary(turns: TurnStats[], steps: StepStats[]): string {
260  if (turns.length === 0) return 'No turns measured yet in this session.'
261  const lines: string[] = []
262  const parts = turns.map(breakdown)
263  const sum = (pick: (b: TurnBreakdown) => number) => parts.reduce((total, b) => total + pick(b), 0)
264  const totals: TurnBreakdown = {
265    totalMs: sum((b) => b.totalMs),
266    waitMs: sum((b) => b.waitMs),
267    thinkMs: sum((b) => b.thinkMs),
268    writeMs: sum((b) => b.writeMs),
269    toolMs: sum((b) => b.toolMs),
270    otherMs: sum((b) => b.otherMs),
271  }
272  lines.push(
273    count(turns.length, 'turn') +
274      ' · ' +
275      formatSpan(totals.totalMs) +
276      ' in all · ' +
277      formatSpan(median(parts.map((b) => b.totalMs))) +
278      ' median'
279  )
280  const split = formatParts(totals, true)
281  if (split !== '') lines.push(split)
282  const byModel = new Map<string, StepStats[]>()
283  for (const step of steps) {
284    const list = byModel.get(step.model) ?? []
285    list.push(step)
286    byModel.set(step.model, list)
287  }
288  for (const [model, list] of byModel) {
289    const out = list.reduce((sum, x) => sum + x.outputTokens, 0)
290    const ms = list.reduce((sum, x) => sum + x.streamMs, 0)
291    const rate = tokensPerSecond(out, ms)
292    lines.push(
293      model +
294        ' · ' +
295        count(list.length, 'request') +
296        ' · ' +
297        formatCount(out) +
298        ' output tok · ' +
299        (rate === null ? '- tok/s' : rate.toFixed(0) + ' tok/s') +
300        ' · ' +
301        formatSpan(median(list.map((x) => x.ttftMs))) +
302        ' median wait'
303    )
304  }
305  if (!turns.some((t) => t.sawThinkingText)) {
306    lines.push('No thinking text was streamed, so thinking is the time before visible output.')
307  }
308  return lines.join('\n')
309}
310
311/** Whole seconds for the live spinner, so it does not flicker: 3400 -> "3s". */
312export function formatLiveSeconds(ms: number): string {
313  return Math.max(0, Math.floor(ms / 1000)) + 's'
314}
315
316/** What the spinner shows after its word while Claude thinks: " · thinking 3s…". */
317export function liveSuffix(startedAt: number, now: number): string {
318  return ' · thinking ' + formatLiveSeconds(now - startedAt) + '…'
319}
320