Run-friction analyzer
OpenSwitchboard can diagnose what cost a run time or made it stumble from its own run-event stream — slow model turns, slow or failed tool calls, retries, setup/install time, wrap-up, budget hits, and exec-infrastructure failures — as a structured, deterministic diagnosis. This is the observe → diagnose half of the self-improvement loop. Everything in this feature is read-only analysis; the propose half — clustering these diagnoses across recent runs and filing deduped issue proposals — is self-improvement.md.
Pure and deterministic (locked design). analyzeRunFriction(events, opts?) is a function of the event stream alone — no clock, no I/O, no mutation of its input. The same events always yield a deep-equal diagnosis, so it runs identically over a live backlog, a saved capture, or a test fixture. That property is what will later let a fix-proposer be tested against recorded runs.
Signals ride the existing stream (locked design). Rather than a second telemetry channel, the run-visibility RunEvent stream (run-visibility.md) was extended additively: every event may carry at (epoch ms, from the runner's injectable clock); a tool_result may carry infra: true when the failure was an ExecInfraError (the sandbox/transport, not the command); and a new run_note variant carries the runner's lifecycle notices as typed kinds — wrap_up, time_budget_exhausted, turn_budget_exhausted, sandbox_dead — alongside the unchanged free-text onProgress. Consumers that only know tool_call/tool_result keep working; the Slack card and live page render notes as a ⏱ line. Redaction is unchanged: findings derive only from already-redacted summaries.
- Code:
src/core/runFriction.ts(analyzeRunFriction,formatFrictionReport,isSetupInstallCommand,formatMs, theFrictionDiagnosis/FrictionFindingtypes);src/core/runEvents.ts(at,infra,run_note/RunNoteKind);src/runner.ts(stampsat, marksinfra, emitsrun_notes);src/core/runRegistry.ts(snapshot(id, token)— token-gated backlog copy + finished flag);src/channels/liveView.ts(GET /runs/:id/friction?t=…);src/core/runEventLines.ts(parseRunEventLines— JSONL or an SSE capture) and the registry commandfriction analyzeinsrc/core/commands/friction.ts(frictionAnalyze,inProgressHint; CLI only). - Tests:
src/core/runFriction.test.ts,src/runner.test.ts(run-friction signals in the event stream),src/core/runRegistry.test.ts(snapshot),src/channels/liveView.test.ts(GET /runs/:id/friction),src/core/runEventLines.test.ts,src/core/commands/friction.test.ts(friction.analyze (CLI only)).
Behavior
- Categories. Each finding has exactly one
FrictionCategory:slow_tool(atool.*span taking ≥slowToolMs, default 30 s;highat ≥ 2×),slow_model_turn(amodel.turnspan taking ≥slowModelTurnMs, default 60 s;highat ≥ 2×; anchored to the turn's ownspan_endand naming what it produced, e.g.model turn took 3m 42s before: $ grep …,(narration),(answer); a 31-min run with 50 s of tool time and 35 one-line greps must not diagnose asno friction detected),failed_tool(ok:false, incl. an unknown tool;medium, orhighwhen the failure also took ≥slowToolMs),retry(the same tool + call summary re-issued after that exact call previously failed; counted per re-issue),setup_install(abashcommand that is a package-manager install /git clone/ similar — incl.python -m pip installandcorepack <pm>wrappers — matched at the start of a shell segment with the subcommand word ending there and quoted strings blanked first, socd x && npm installcounts whileecho npm install,echo "cd x && npm install",npm ci-lockfile-report, andnpm testdo not),wrap_up(the runner's wrap-up note; its extent is from the note to the end of the window),budget_hit(time- or turn-budget exhaustion note,high; no extent),infra_failure(aninfra:trueresult — the finding names the command that was running — thesandbox_deadandfleet_busynotes (no extent), or — in a finished stream — atool_callwith no result, i.e. the run died mid-tool, whose extent is the open tool span's; allhighbutfleet_busy). Every duration comes from ONE span set (tracing.md item 14): the stream normalized bynormalizeSpans— a tool pair whose twin span the record budget dropped gets it back from the pair's own stamps — so a finding carries the duration of the span it is about, and a stream with nomodel.turnspans has no model time and noslow_model_turn, whatever the gaps between its content events. - Precedence — one finding per event.
infrabeats everything (a dead sandbox is not a failing command);setup_installbeatsfailed_tool/slow_tool(a slow or failed install is still setup cost, so the category total is the true install bill; a failed install ishigh); thenfailed_tool; thenslow_tool.retryis anchored to the re-issued call and is additional to whatever its result yields. - Timings are optional, and there is one code path. A stream is timed when a content event carried
ator a window was given:runMs— the run's window (receivedAt→finishedAt, or now while live) when the caller passes one, else first→last content stamp (a stdin capture);toolTimeMs(the sum of thetool.*spans);modelTimeMs(the sum of themodel.turnspans, present only when the stream had a turn); per-findingdurationMs; per-categorydurationMs— the sum of the findings' durations for the tool-denominated categories andslow_model_turn(its turns are disjoint, so the sum is the union), the union of the findings' intervals forwrap_up,budget_hitandinfra_failure(three calls of one batch dying together are one interval, not three).DENOMINATOR_OFnames what each category's time is a share of — tool time forslow_tool/failed_tool/retry/setup_install, run time for the rest — so no share can exceed 100 %. For an agent runthinking ≤ model timeandtools ≤ tool timehold by construction (a union is at most a sum over the same span set); a command run'stoolsbucket is the command's own work and the report prints notool calls/tool time/model timeline for it. Without timings — a hand-written capture, a record from before spans — nothing is special-cased: the same classification, and every timed field is simply absent (a pair without a stamp gets no span, so no duration;runMs,toolTimeMs,modelTimeMsare absent; the report prints-in the time column and norun/tool time/model timetotals). The shape (tracing.md item 5): with a window andfinished, the diagnosis carriesshape— the window's seven terms frompartitionover the same span set (windowMs,gettingReadyMs,thinkingMs,toolsMs,finishingUpMs,overheadMs,notRecordedMs,notLoadedMs),ownerdeciding whetherrun.commandis tools (a command run) or getting ready; the finish-site diagnosis is what the run record stores and the closed Slack card's shape line reads, so the card, the record and the report agree. Live, or without a window, there is no shape. Every duration surface prints throughformatDuration(reportstyle, hours included). - Verdict. One line naming the dominant cause: the category with the most attributed time (ties → most findings → category order), with its share of its denominator (
DENOMINATOR_OF:… (60% of run time)for the run-denominated categories,of tool timefor the tool ones); without timings, the category with the most findings;no friction detectedwhen there are no findings. The verdict names the dominant friction category and the shape names the dominant bucket — two lenses on one span set, printed one under the other. Labels are one vocabulary:slow tool calls,slow model turns,failed tool calls,retries,the repo's setup/install,agent wind-down,budget hits,infra failures— the verdict, the report's category table (column sized to the longest), its finding lines and the friction proposals' titles all print them, never the category ids.byCategoryalways contains every category (zeroed), so consumers need no undefined checks. Findings are in stream order, each anchored to aneventIndex. The text report printsevents, thentool callsandtool timeonly when a tool ran,runwhen timed,model timeonly when the model turned,(input truncated — some records were dropped before analysis)when the input lost records, andshape: <line>beneath the totals when the diagnosis has one (<total> (one bucket)when fewer than two buckets are informative). - Mid-run vs finished.
opts.finished(defaulttrue) controls whether a trailing unpairedtool_callis friction: in a finished stream it is aninfra_failure("no result … run ended mid-tool"); in a live one it is simply still running. - Read-only surfaces.
GET /runs/:id/friction?t=<token>returns{ id, finished, diagnosis }as JSON (no-store, GET-only → 405) for any run still in the registry — live or finished within the TTL — behind the same constant-time capability-token gate as the page and stream (wrong/missing token or unknown run → 404, existence never revealed).npx tsx src/cli.ts friction analyze [source] [--slow-ms n] [--in-progress] [--json](CLI only; stdin for-) analyzes a saved stream: JSON lines ofRunEvents, or a raw SSE capture of/runs/:id/events(curloutput —data:frames;retry:/event:/comment lines and theendpayload are skipped). Input is external, so each line is shape-checked (stringtool/summary, booleanok, knownkind, numericatwhen present) — a recognizedtypealone is not enough; malformed lines are skipped and counted, never fatal (the analyzer itself also tolerates a non-string summary); zero events → exit 1.--in-progressmarks a mid-run capture (finished:false) so a trailing unpaired call is not misread as a dead run; without the flag, a stream that ends on an unpaired call gets a stderr hint pointing at--in-progress. Neither surface mutates anything.
Validation criteria
| Criterion | Evidence |
|---|---|
Empty stream → zeroed diagnosis, no findings, no friction detected | [unit] src/core/runFriction.test.ts::analyzeRunFriction — empty / untimed input::an empty stream yields a clean, zeroed diagnosis… |
Clean fast run → no findings; runMs/toolTimeMs computed | [unit] ::a clean, fast run has no findings and a no-friction verdict |
| Untimed stream (no stamps) still classifies, with no durations and no timed fields | [unit] ::untimed events (a hand-written capture) still classify failures/retries, with no durations |
| Deterministic; input not mutated | [unit] ::is deterministic: the same stream yields a deep-equal diagnosis, ::does not mutate its input |
slow_tool at threshold, high at 2×, not flagged under | [unit] ::slow_tool: a tool call whose result arrives past the slow threshold, ::slow_tool: ≥2× the threshold is high severity; under the threshold is not flagged |
slow_model_turn at threshold (default 60 s, configurable), high at 2×, not flagged under; anchored to its model.turn span end and naming the produced event; modelTimeMs summed | [unit] analyzeRunFriction — slow_model_turn…::flags a model turn at or past the threshold…, ::≥2× the threshold is high severity; the threshold is configurable |
A narrating completion is one turn naming (narration); the answer is the last turn's product; a stream without model.turn spans has no model time and no slow turn whatever its gaps | [unit] ::a narrating completion is one turn…, ::the final answer is the last model turn's product… |
Untimed streams: no slow_model_turn, no modelTimeMs | [unit] ::untimed streams never produce slow_model_turn and carry no modelTimeMs |
| Verdict share for dominant model time is of run time, never tool time | [unit] ::the verdict for dominant model time is a share of RUN time (tool time would exceed 100%) |
failed_tool incl. unknown tool; high when the failure was also slow | [unit] ::failed_tool: an ok:false result (including an unknown tool), ::failed_tool severity scales with how long the failure took |
| Analyzer tolerates a non-string summary from an external capture | [unit] ::tolerates malformed field types from an external capture (non-string summary/tool) without throwing |
infra_failure finding names the command that was running | [unit] ::infra_failure: an infra-flagged tool result is an infra failure (asserts the call summary is in the finding) |
retry only after a failure of the same call; repeats without failure are not retries | [unit] ::retry: the same call re-issued after it failed…, ::retry: a repeated call that never failed is NOT a retry (red-verified: disabling the failed-call check fails these) |
setup_install classification, totals, precedence over slow/failed, package-manager coverage, segment-start matching | [unit] ::setup_install: install/clone commands are classified with their total time…, ::setup_install: a FAILED install is classified as setup (high)…, ::setup_install: recognizes the common package managers… (red-verified: disabling the install branch fails these) |
wrap_up with wind-down duration; budget_hit for both budget kinds; infra_failure for infra:true and sandbox_dead | [unit] ::wrap_up: …, ::budget_hit: …, ::infra_failure: an infra-flagged tool result…, ::infra_failure: the sandbox_dead note… |
Finished stream: unpaired trailing call → infra_failure; unfinished: not flagged | [unit] ::an unpaired trailing tool_call (run died mid-tool) is reported as an infra failure, ::an unpaired trailing tool_call in an UNFINISHED stream (finished:false) is not flagged |
Verdict = most time (with share) / most findings without timings; byCategory complete | [unit] ::the verdict names the category that cost the most time…, ::with no timings the verdict falls back…, ::byCategory always lists every category |
Text report renders verdict, totals (incl. model time), category table, findings | [unit] formatFrictionReport::* |
Runner stamps at from its clock on every event | [unit] src/runner.test.ts::run-friction signals…::stamps every event with \at`…` |
Runner marks ExecInfraError results infra:true and nothing else | [unit] ::marks an ExecInfraError result with infra:true; an ordinary tool error is NOT marked |
Runner emits run_note for wrap-up, turn/time budget exhaustion, sandbox death | [unit] ::emits a run_note for the wrap-up warning and for turn-budget exhaustion, ::emits time_budget_exhausted…, ::emits sandbox_dead… |
| Existing consumers unaffected: card + registry receive notes; page renders them | [unit] src/core/dispatcher.test.ts::live run-view wiring…::registers the run, publishes its events, and finishes it (asserts the note reaches the registry) |
snapshot is token-gated, returns a copy + finished flag | [unit] src/core/runRegistry.test.ts::snapshot — token-gated read of a run's backlog …::* |
/runs/:id/friction: route parsed; 404 on bad/missing token; JSON diagnosis (no-store, 405 non-GET); mid-run finished:false | [unit] src/channels/liveView.test.ts::GET /runs/:id/friction…::* |
parseRunEventLines parses JSONL and raw SSE captures, skips garbage AND wrong-shaped events; friction analyze [source] [--slow-ms n] [--in-progress] reads a file or stdin, renders the report + skipped count, --slow-ms/--in-progress reach the analyzer, a missing file is not_found, a stream without events invalid_input, and the command is CLI-only | [unit] src/core/runEventLines.test.ts::*, src/core/commands/friction.test.ts::friction.analyze (CLI only) — the former frictionCli::* |
The --in-progress hint appears only when a default analysis blames a trailing unpaired call | [unit] src/core/commands/friction.test.ts::friction.analyze (CLI only)…::--slow-ms and --in-progress reach the analyzer… |
| CLI end-to-end over a saved SSE capture prints a report | [agent] npx tsx src/cli.ts friction analyze <capture.sse> on a curl-saved /runs/:id/events stream → a verdict: line, totals, category table, findings. |
| Friction JSON of a real deployed run via the live link | [gap] Open <live link> with /events replaced by /friction on a finished run within the TTL → 200 JSON with a plausible verdict. |
3: with a finished window runMs is the window, model/tool time are the spans' sums, shape partitions the window and its identity holds; the slow turn anchors to its span end and names the call it produced | [unit] src/core/runFriction.test.ts::analyzeRunFriction — the window, the shape and the span set (docs/reference/specs/tracing.md)::with a finished window… |
3: no window (a capture) → no shape, runMs first→last; live with a window → no shape; an open turn on a live read counts to the window's end | [unit] ::without a window (a stdin capture)…, ::a live read: an open model turn runs to the window's end… |
3: a command run's run.command is its tools; the same stream as an agent run is getting ready | [unit] ::a command run's window: \run.command` is its tools` |
3–4: run-denominated categories take the union of their findings' intervals (a batch dying together is one interval), DENOMINATOR_OF covers every category, the share never exceeds 100 %; wrap-up runs to the window's end, a budget hit prints - | [unit] ::run-denominated categories take the UNION…, ::wrap-up runs from the warning to the window's end…, ::every category names its denominator |
| 4: the report's shape line, the gated totals lines, the labels | [unit] ::the report: the shape line under the totals…, formatFrictionReport::renders the verdict, totals, a per-category table, and each finding on one line |
1, 3: differential — a record whose tool.* twins the budget dropped is timed like the full stream (the pairs' own stamps); a record with no span records at all is a content stream: the window, the pairs' tool time, no model time; a model.turn span is not a step and never moves the clock | [unit] ::differential: a record whose tool.* twins the budget dropped…, src/core/runFriction.test.ts::analyzeRunFriction — narrative events are not steps…::a \model.turn` span is not a step…` |
3: the record's diagnosis is the finish-site one over the run's window and carries the shape; /runs/:id/friction and the service pass the window and the live schema | [unit] src/core/dispatcher.test.ts::friction diagnosis reads the registry backlog …::the run record's diagnosis — what the friction ledger reads…, src/core/runsService.test.ts::RunsService.getRunFriction::passes the injected analyzer the live events and finished flag |