PR #311 - sysprog21/codetrial

When a candidate finished speaking, nothing said where the wait before the interviewer (Jim, the Gemini Live voice) answered went in enough detail to act on, and a Live socket that hung on an unstarted reply was waited on for the full 45-second reply timeout. This adds a per-reply latency record and scripts/analyze-latency.py, then uses what they show to make fewer of the slow replies and to bound the ones that never start. It sits beside the per-turn turn_timing summary from #294; folding the two into one instrument is a follow-up.

Where the wait goes

Each reply is traced from the candidate's last voiced audio frame (or the platform prompt that asked for it) to the moment its first audio frame is handed to LiveKit, and split into consecutive segments that add up to the total. Network and browser playback after that point are not measured.

Two data sets are used throughout, both on gemini-3.1-flash-live-preview with the acknowledgement off:

Interview: one 18-minute interview on the latency commit with default settings (3 s silence window), 29 replies, no stalls. The diagrams use it.
Barge: eight 4-turn sessions in which a scripted candidate ends each turn with the yield button instead of waiting out the window, 41 replies, no stalls.

The headline: in the interview, a spoken reply with no tool call came 404 ms after the silence window at the median, and one that called a tool first came 1124 ms after it. The tool call adds 720 ms (95% CI 620 to 805).

Red is waiting on Gemini, network uplink included; blue is CodeTrial; grey is a setting.

flowchart LR
  A([Candidate stops speaking]) --> W["Silence window<br/>3000 ms, a setting"]
  W --> E["Gemini end of speech and first output<br/>p50 390 ms past the window,<br/>sent together"]
  E -->|"no tool call<br/>10 of 22 replies"| F["Gemini first audio<br/>p50 4 ms later"]
  E -->|"tool call first<br/>12 of 22 replies"| T["Gemini tool call<br/>p50 2 ms later"]
  T --> X["CodeTrial runs the tool<br/>p50 1 ms"]
  X --> P["Gemini second pass<br/>p50 714 ms"]
  F --> Q["Output queue and capture<br/>p50 2 to 8 ms"]
  P --> Q
  Q --> H([Jim's first audio frame])
  classDef gemini fill:#fadbd8,stroke:#c0392b,color:#000
  classDef local fill:#d6eaf8,stroke:#2471a3,color:#000
  classDef setting fill:#eaeded,stroke:#7f8c8d,color:#000
  class E,F,T,P gemini
  class X,Q local
  class W setting

The same segment medians laid end to end, to show scale. Sums of medians are not medians of sums, so the bars end within 10 ms of the measured totals rather than on them:

gantt
  title Segment medians laid end to end, 3 s silence window
  dateFormat x
  axisFormat %S.%L s
  section No tool (measured p50 3.40 s)
  Silence window (setting)        :done, w1, 0, 3000
  Gemini end of speech and audio  :crit, g1, 3000, 3398
  Output queue                    :q1, 3398, 3400
  section Tool call (measured p50 4.12 s)
  Silence window (setting)        :done, w2, 0, 3000
  Gemini end of speech            :crit, g2, 3000, 3390
  Tool call and execution         :t2, 3390, 3393
  Gemini second pass              :crit, p2, 3393, 4107
  Output queue                    :q2, 4107, 4115

Time past the silence window, summed over all 29 interview replies:

%%{init: {"themeVariables": {"pie1": "#c0392b", "pie2": "#e74c3c", "pie3": "#f1948a", "pie4": "#fadbd8", "pie5": "#2471a3"}}}%%
pie showData
  title Time past the silence window (%)
  "Gemini, after the tool response" : 43.8
  "Gemini, end of speech" : 34.9
  "Gemini, first audio for a prompt" : 12.9
  "Gemini, deciding on a tool call" : 7.0
  "CodeTrial, tool, queue and capture" : 1.4

How to read it:

The silence window is most of what a candidate waits: 3.0 s of a 3.4 s reply, 3.0 s of a 4.1 s one. It is a setting, traded against cutting off a candidate who paused to think, and this PR leaves it alone. The yield shortcut (Alt+Enter) replaces it with the candidate's own time; in the barge sessions the scripted yield came 1.0 s after the last voiced frame, which is a property of the test clip, not of people.
Past the window, 98.6% of the time is spent waiting on Gemini, network uplink included. CodeTrial's own work (tool execution, the output queue, LiveKit capture) is 1 to 8 ms at the median and 38 ms at p95.
Gemini sends its end-of-speech signal together with its first output (21 of 22 spoken replies), so the 390 ms past the window covers uplink, Gemini's voice detection and the model's start, which these records cannot separate. A plain reply's audio follows 4 ms later. A tool call instead sends CodeTrial a request, and the reply waits for the answer and a second model pass, 714 ms at the median.
A platform prompt has no window, so the model's start shows in full: 831 ms (interview) and 706 ms (barge) from the prompt to Gemini's first output.

The factors, ranked

"Size" is what the factor costs: for the tool call, how much later a spoken reply arrives when a tool call came first (difference of medians, 95% bootstrap interval); for the other rows, where the factor applies and its share of the time past the window. "Spread" is the share of the reply-to-reply variation in time past the window that moves with each segment (its covariance with that time over the time's variance). Spreads sum to 100% across segments and go negative when a segment is longer on replies that are quicker overall, as end of speech is on plain replies.

Factor	Owner	Median	Size	Spread, interview / barge	Lever
Silence window	setting	3000 ms	73 to 88% of the total wait	fixed	product decision; yield shortcut
Second pass after a tool call	Gemini	714 ms interview, 786 ms barge	+720 ms (620 to 805) interview, +877 ms (730 to 1029) barge	93% / 86%	fewer tool calls; acknowledgement
End of speech past the window	Gemini, uplink	390 ms interview, 224 ms barge	every spoken reply, 35% of the time	-12% / 4%	provider voice detection, untested
First output for a prompt	Gemini	831 ms interview, 706 ms barge	prompt replies, 13% of the time	-3% / -10%	none found
Thinking before a tool call	Gemini	2 ms spoken; 564 ms after a prompt (n=3)	prompt replies; a spoken tail in barge (p95 657 ms)	20% / 20%	none found
CodeTrial's own work	CodeTrial	1 to 8 ms	1.4% of the time	2% / 0.4%	already small
Conversation length	Gemini		-0.3 ms per 1k tokens over 5k to 47k tokens (interview)	none	none needed

The tool call is the one factor in the reply path that is both large and partly in CodeTrial's hands, because the prompt decides how often the model calls tools. This PR keeps blocking tool calls (see Left out), makes fewer of them, and offers an acknowledgement for the rest.

What changes

Bounded unstarted replies. A reply with no output yet, including one whose generation stopped after a tool response, now gives up the socket once CODETRIAL_GEMINI_FIRST_OUTPUT_S has passed, unless Gemini reports the candidate still speaking. The default is 10 s, the minimum 5 s, and it is capped at the reply timeout (45 s by default); it is checked on the 2 s watch tick and measured from the newest outstanding request. Before, such a reply waited the full reply timeout. A recovery (a replacement's briefing or a reply check) gets at least 10 s while it is the newest request, so a shorter setting cannot cut one recovery straight into the next.
Fewer tool calls. Live prompt 26 (bundle 35) stops the opening turns reading the starter editor, defers unrecorded earlier steps to the next evidence call, and leaves Repeat, Example and Algorithm to the phase judge until Coding is recorded. The coding silence nudge now says whether the candidate has written code, instead of offering both branches, which had the interviewer read the editor to choose, and once understanding, example and algorithm are recorded it asks them to begin coding. The read_editor guidance says a language named aloud needs no read.
Evidence off the editor reply path. At a typed editor the interviewer is no longer given record_framework_evidence, each call of which held its reply back by a second model pass, and is told the platform records every step and that the editor is not to be read to learn whether one was. The phase judge records what only the tool recorded there: Test from a hand trace while nothing can run the written code, and the STAR steps, quoted only from inside the behavioral round and not from a story the interviewer told first. It can report a declined probe, and the platform writes the end-of-session skips for a started round that the wrap-up used to ask the interviewer for, except where the probe was declined. Repeat, Example and Algorithm stay open after Coding while a step about the code is, so one explained late is still recorded; written code goes with every coding-round judgment, so a hand trace is judged against what it traces, and an explanation the candidate typed as a comment, read as the editor's language writes comments, may be the quote, recorded as an editor snapshot. Test runs no longer remind the interviewer of earlier steps to record, nor ask it to record Optimizations again after a rewrite. The coding round's routine judgments leave 8 of the 48 for a behavioral round still to come; the end and a round transition may use them. A whiteboard keeps the tool and its wording, byte for byte, since the judge is not shown the board, and its judge records neither STAR nor a hand trace and holds no reserve.
Acknowledgement. CODETRIAL_GEMINI_TOOL_ACK, off by default. When enabled, one request per interview to gemini-3.1-flash-tts-preview, on the report keys, generates "Mm, okay." in the session's voice and accent; if it is not ready or fails, nothing plays. It plays when a tool call holds back a reply the candidate is waiting for and has heard nothing of, never while they speak again, while the floor is held, or before a goodbye. The reply's first audio cuts whatever of the clip is still queued or playing; audio already sent cannot be recalled.
Smaller local costs. The agent-state write moves off the room loop, microphone audio goes out in 20 ms batches, and a hold always cuts a generation in progress. A provider interruption no longer settles a reply nobody heard, and a turn that answered a waiting candidate with tool calls alone gets one note asking for the reply if one is due.
Analyzer. Reports replies past --stall-ms (5 s) as a rate instead of letting them set the tail, splits replies by whether a tool call came first, and fits growth with context within each kind of reply, so a long interview does not read as slowing down just because later turns call more tools. --compare sets a log against an earlier one kind of reply by kind and splits the change in the mean into mix and speed (see Results).

The series is six commits: the latency work; the silence nudge; the acknowledgement; a fix to tests/browser/interviewer-voice.test.js, which failed on any machine running a sound server because Chromium's fake-microphone beep is too short for the check that enables Join, and now captures test-voice.wav like the two other tests that need a working microphone; the run comparison, held to --strict as well; and evidence recording off the editor reply path, where the end and a round transition may use the behavioral reserve and the judge rereads a round that opened at a turn in flight. The fixes from cubic, the mutation gate and two rounds of agy, codex and claude review are folded into the commits they correct: the second round's covered what the evidence tool left at the editor (test-event reminders, late planning steps, comment quotes read per language and recorded as editor snapshots, hand traces judged with the code and kept spoken, and a behavioral round that made a judgment due over an empty round and could leave an answer unread), a cleared editor in the silence nudge, the acknowledgement across an interruption that keeps the wait, and the comparison's mix and speed for an origin seen on one side only. The nudge, the acknowledgement and the evidence change stay revertible on their own. The rustls bump this branch used to carry landed on main in #314.

Results

All runs on this Linux host against gemini-3.1-flash-live-preview, analyzed with the current scripts/analyze-latency.py. Sets under 20 replies are small, and their p95 is close to their maximum.

Before and after: what the prompt change did (barge flow). The barge flow is the scripted candidate described above. "Old prompt" is 10 sessions in two run sets before this PR's prompt and first-output deadline; "new prompt" is 38 sessions in nine run sets after them, the last four re-measured on the tip. A single run each is not enough to compare: on the same old code, the median tool reply came 850 ms past the yield in one run and 1195 ms in the next, an hour later, so provider speed alone moves a run's median by a few hundred milliseconds. The table is the output of scripts/analyze-latency.py --compare old.log new.log, spoken replies, time past the yield:

	old prompt	new prompt
replies that called a tool first	23 of 23 (100%)	66 of 104 (63%)
median, replies with no tool call	none	239 ms
median, replies with a tool call	917 ms	1045 ms (shift +128 ms, 95% CI -84 to +228: no change)
mean, all replies	1014 ms	855 ms (-159 ms)
of which: fewer tool calls (mix)		-266 ms
of which: each kind faster or slower (speed)		+107 ms
stalls (5 s or more past the yield)	3 of 44, 13.6 to 16.5 s, all waiting on a tool decision	5 of 191, all in two early sets of this work; 0 of the 121 since

How to read it: no kind of reply got faster. Tool replies ran within the 815 to 1281 ms range their medians span across all run sets whatever the code, and that provider drift is the +107 ms. What changed is how many replies need the tool call at all: 37% now skip it and arrive about 0.8 s sooner, worth 266 ms on the mean. The stall difference fits the deadline but is too few events to prove it.

Acknowledgement, barge flow, spoken replies that called a tool:

%%{init: {"themeVariables": {"xyChart": {"plotColorPalette": "#2471a3"}}}}%%
xychart-beta
  title "Tool replies, p50 ms past the yield"
  x-axis ["Off (n=18)", "On, reply waits (n=7)", "On, reply cuts it (n=8)"]
  y-axis "ms" 0 --> 1400
  bar [1087, 1306, 965]

Off: p50 1087 ms (95% CI 1022 to 1239), output-queue p95 23 ms. It pools three session sets, including a first "on" round that played nothing, because the speech model answers audio/l16 in lower case; the MIME check is now case-insensitive and tested with that exact type.
On, with the reply waiting behind the clip: p50 1306 ms (CI 936 to 1917), output-queue p95 699 ms. The clip was queued a median 1459 ms before the reply's capture (n=4).
On, with the reply cutting the clip: p50 965 ms (CI 851 to 1083), output-queue p95 25 ms, and the clip queued about 1 s before the reply's capture (n=2). Against off, the difference is 122 ms with a 95% interval from 321 ms lower to 7 ms higher, so it is not distinguishable from off: the cut removes the penalty, and the acknowledgement neither speeds nor slows the reply.
It stays off by default until it is heard in real interviews; browser playback of the clip was not measured.

Long interviews, 18 minutes each, context up to about 47k tokens:

Acknowledgement off (the interview data set): 29 replies, two resumed handovers at the Live connection cap, no stalls, recoveries or cold restarts; past the window p50 1012 / p95 1328 ms; no growth with context (-0.3 ms per 1k tokens).
Acknowledgement on, before the reply could cut it: 34 replies, one resumed handover, no stalls or recoveries; p50 788 / p95 2169 ms. The longer tail is the clip in the reply's way (tool replies' output-queue p95 855 ms), which the cut removes. The clip played for 3 replies, queued 1.8 s before each reply's capture; silence-nudge tool calls get none, since nobody is waiting. read_editor was 5 of 10 tool calls, within the range of the earlier long runs, so one session shows no measurable reduction from the nudge change.

First-output default. It stays 10 s. Across 367 earlier replies, ordinary first outputs topped out at 2.7 s and hung ones ran 7.2 to 27 s, which made 5 s look safe. An 18-minute run at 5 s then failed at minute 4: a reply with nothing back 5.8 s after Gemini's end of speech replaced the socket, the resumed socket's briefing was cut at 5.3 s too, and the interview fell back to a cold rebuild, 12.8 s after end of speech and with the resumed conversation lost. That run predates the recovery floor described above, which stops the second cut. A run at 10 s went the full 18 minutes with no recovery. One run each cannot isolate the deadline's effect, so 5 s stays a setting rather than the default.

Measured again, and what came of it

A second round on the tip, with the method above built into the analyzer (--compare, tool_share): three arms interleaved over the same hour so provider drift falls on all of them alike, four barge sessions each.

arm	tool call first	no tool, p50	tool, p50	end of speech, p50	stalls
yield button (baseline)	7 of 11	271 ms	935 ms	187 ms	0 of 20
silence window, default end sensitivity	8 of 12	304 ms	1144 ms	358 ms	0 of 20
silence window, `GEMINI_END_SENSITIVITY=HIGH`	9 of 12	400 ms	1107 ms	396 ms	0 of 20

The per-kind times reproduce the first round, so the tool call is still the lever.
A higher end-of-speech sensitivity does not shorten the wait: end of speech moved +39 ms (95% CI -71 to +108, n=12 each), and the comparison puts the mean at +13 ms (mix +70, speed -58). The default stays the API's own.
Two in three spoken replies still wait on a tool call with the new prompt. 60 of the 66 tool replies called only record_framework_evidence, and every evidence row the interviewer recorded in these logs was Repeat, Example or Algorithm: the steps the prompt tells it to leave to the phase judge, which records them anyway. Leaving the three steps out of the tool's phase enum did not stop it either; in one interview the model made 12 such calls, all rejected, each still a tool round.

Proposals, ranked by expected effect:

proposal	basis	expected effect	status
Take evidence recording off the reply path: drop `record_framework_evidence` from sessions where the phase judge and test runs cover every REACTO step, or otherwise stop the interviewer recording Repeat, Example and Algorithm	60 of 66 tool replies called only that tool; tool replies average 1144 ms past the yield, others 351 ms	tool share from 63% to about 6%; about -0.46 s on the mean spoken reply, if the freed replies behave like today's replies without a tool call	done, last commit; measured below
Acknowledgement on by default	queued 1 to 1.5 s before the reply on tool replies	candidate hears something sooner on the remaining tool replies; reply time unchanged	needs listening in real interviews
Compare runs kind by kind (`--compare`, `tool_share`)	two runs' medians misled	measurement only	done
Higher end-of-speech sensitivity	end of speech is on every spoken reply	none measured	tested, not adopted

Evidence off the reply path, measured. Old is the tip before the change, new the change itself, interleaved over the same hour, barge flow with the yield button. The first round (four sessions each) found the tool calls gone but as many tool rounds as before: without the evidence tool's replies the model read the editor to learn whether a step was recorded (read_editor 1 to 6 calls). The prompt now says not to; the second round, five sessions each, is the code as committed:

spoken replies, past the yield	old	new
a tool call first	9 of 14 (64%)	2 of 15 (13%)
median, no tool call	237 ms	220 ms
median, tool call	956 ms	922 ms
mean	819 ms	506 ms (-314 ms)
of which: fewer tool calls (mix)		-295 ms
of which: each kind faster or slower (speed)		-18 ms
`record_framework_evidence` / `read_editor` calls	10 / 1	0 / 6
steps recorded (Repeat, Example, Algorithm)	5, 5, 4	5, 4, 4, all by the phase judge
stalls	1 of 26	0 of 25

The change does what the first measurement predicted: almost the whole drop is mix, and no kind of reply got faster or slower. The estimate was -0.46 s from 63% to 6%; the measured share fell to 13% and the mean by 0.31 s.
The phase judge recorded the coding steps as often as the interviewer and the judge did together before, so nothing the checklist shows was lost in these sessions.
Four of the six read_editor calls came after the reply had started, so they held nothing back. The one stall in the first round was the provider not answering a reply at all; the first-output deadline replaced the socket and the reply came 12 s after the yield, on the new code, with no tool involved.
Not measured live: the STAR steps and a hand-traced Test. The scripted candidate never writes code, so no session reaches the behavioral round or a runner outage; those paths are covered by unit tests only.

Left out, with the evidence

The remaining tool calls stay blocking. With NON_BLOCKING tools Gemini 3.1 Live ended its turn without speaking, and an enum restricting the evidence tool's phases was ignored, which is why the tool is removed at the editor rather than narrowed. A whiteboard keeps it, since the judge is not shown the board.
A dedicated first-output timer in place of the 2 s watch tick: no stall appeared in the last 81 replies measured, and the timer would sit in room-loop code no unit test reaches.
A shorter silence window: it is the largest segment, but shortening it cuts off candidates who pause, which needs a product decision and a matched comparison rather than a latency PR.

Verification

After the review fixes, ./scripts/test.sh passes every gate; each new test was checked to fail with its fix reverted. Folding them changed no file: the folded tip is byte-identical to the tip CI passed, and cargo test passes at every commit.
After rebasing onto main and folding the review fixes into their commits, the tree is byte-identical to the previous tip, every commit passes cargo check --all-targets, and ./scripts/test.sh at the tip passes every gate; one browser test new on main (disabled execution hides the test drawer divider) failed once while the per-commit build ran beside it and passed in six reruns and in a full rerun of all 1153 browser tests.
./scripts/test.sh on the evidence commit: every gate passed except fmt and indent, which flagged line wrapping in two new test assertions; after make indent those two lanes, clippy and cargo test pass again. The regenerated prompt golden changes no whiteboard prompt. On the commits before it every gate passes, browser-tests included now that the preflight test has a speaking microphone. cargo-audit and shellcheck are not installed here and were skipped. cargo test, clippy and the analyzer's Python tests also pass at the latency, silence-nudge and acknowledgement commits on their own. One run at the latency commit, here and in the previous round, reported a single failing test that no rerun reproduced (50,000 runs at the tip, 15 of the full suite under triple load, also clean); its name was not captured, and the loops now keep full logs.
Mutation testing: tests now kill the 57 mutants the previous push left alive, except the two print-only log functions, which are excluded with the reason in .cargo/mutants.toml, as are the room-side wrappers play_tool_ack and tool_ack_clip, whose decisions are tested in tool_ack_fits, take_tool_ack and tool_ack_clip_at, and the NativeAudioSource shim the output worker goes through, which is libwebrtc like the worker itself; the worker's ordering of capture and cancellation is tested against a recording sink. Locally, cargo mutants over the changed prompt lines with the full suite caught all 15; CI's mutation lane passes on the tip.
Statistics: medians with 95% bootstrap intervals over replies (20,000 resamples). Resampling replies ignores what replies in one session share, so the intervals are if anything too narrow.

Summary by cubic

Measures where the wait for an interviewer reply comes from, stops waiting the full 45-second reply timeout on replies that never started, and cuts tool rounds off the reply path at a typed editor.

Faster, better-bounded replies

A reply nothing has started toward is replaced after CODETRIAL_GEMINI_FIRST_OUTPUT_S (default 10 s, never above the reply timeout); a recovery is never held below that default while it is the newest request.
Agent-state writes move to a background writer, microphone audio goes out in 20 ms batches, and a hold always cuts active generations; a provider interruption no longer settles a reply nobody heard, and a tool-call-only turn gets one follow-up prompt when a reply is owed.
Live prompt 27 (bundle 36) keeps the opening turns from reading the starter editor, defers unrecorded earlier steps, and the silence nudge states whether the candidate wrote code.
At a typed editor record_framework_evidence is no longer declared; the phase judge records Test from a hand trace and the STAR steps, reads typed comments as editor snapshots, keeps a hand-traced Test speech-only, and the coding round reserves judges for a behavioral round.
CODETRIAL_GEMINI_TOOL_ACK (off by default) plays a short acknowledgement while a tool round holds a reply; the reply's first audio cuts it.
The browser voice preflight captures test-voice.wav so it no longer fails on a machine running a sound server.

Observability

Adds docs/latency-observability.md and per-reply latency logs, broken down by scripts/analyze-latency.py into endpointing, provider first output, tool rounds and output queue.
The analyzer reports stalls as a rate and, with --compare, splits a change in the mean into mix (share of tool replies) and speed; its tests run in the gate.