A turn can receive bytes for 57 minutes and produce nothing — instrument per-request chunks, bytes and tokens so "generating slowly" is distinguishable from "receiving nothing useful" #280

Merged

toasterson merged 1 commit from claude/wi-019fb9d7-a-turn-can-receive-bytes-for-57-minutes into main 2026-07-31 21:44:20 +00:00

Conversation 0 Commits 1 Files changed 6 +241 -17

toasterson commented 2026-07-31 20:49:53 +00:00

Owner

Copy link

Anima work item 019fb9d7-395c-74b0-8f91-7bfcef1bf03b.

What happened

Session 019fb977-d7ff-70f3-b89f-d15f18566c65, workspace tecton, WI-259,
on image 0fc0416b257d (post-#279):

18:37:46  session.started
18:40:53  ONE agent_thought — "Let me start by understanding the current state…"
   …      57 minutes, nothing
19:38:00  agent_message, 1423 chars, ending "Let me now examine the actual code…"
19:38:00  turn_completed {"outcome":"failed","stop_reason":"cancelled",
                          "error_text":"turn killed by the 3600s budget cap —
                                        the agent produced no durable output"}

The agent had understood its task correctly — it read the review verdict and
enumerated the 15-file blast radius back accurately. It then produced 1423
characters in 57 minutes and nothing durable.

Why the existing signals cannot explain it

Both supervision mechanisms stayed silent, and each silence is informative:

• Idle watchdog: never fired. grep -c "chat turn stalled" = 0. #279's
  heartbeat did its job — this is no longer a false kill.
• Socket read timeout (AKH_SOCKET_READ_TIMEOUT_SECS, default 60s): never
  fired. So bytes were arriving on the socket at least every 60 seconds for
  the entire hour. The connection was alive and the provider was delivering.

So this is neither a hang nor a dead socket. Something was being received,
continuously, and almost none of it became work. We currently have no way to say
what. Until #279 landed, the watchdog killed these turns at 2700s and mislabelled
them empty, so the question could not even be asked.

What to instrument

Per LLM request, at completion (and on cancellation), one structured log line:

• chunks_received, bytes_received
• counts by kind: content deltas, thinking deltas, tool-call chunks, keepalive-only
  chunks (a chunk that yielded no visible event)
• prompt_eval_count / eval_count from Ollama's final message, and wall duration
• request_seq within the turn, so a turn that issues 40 requests is
  distinguishable from one that issues a single 57-minute request

That single line separates the live hypotheses, which today we cannot choose
between:

1. one enormous slow generation — few requests, high eval_count, steady bytes
2. a retry/roundtrip loop — many requests, low eval_count each
3. thinking that never converges — thinking deltas dominate, content and
   tool_calls near zero (note reasoning_effort = "high" is set on tecton and
   the model advertises a 1,000,000-token context window)
4. received-but-discarded — bytes arrive, nothing parses into an event

Also worth capturing

• Log the prompt size actually sent. A 1M context window plus a large repo
  brief may be producing pathological latency; right now nobody can see the input
  size at all.
• Emit the same counters on the cancellation path, not just clean completion —
  the interesting turns are the ones that get killed.

Acceptance

• One structured line per LLM request carrying the counters above, present on
  both the completed and cancelled paths.
• Re-running the WI-259 turn shape yields a log that identifies which of the four
  hypotheses holds.
• The counters are cheap enough to leave on permanently (counters and one line per
  request, not per chunk).

Context

Related: WI-271 (the heartbeat, merged as #279) — this item exists because that
fix worked and stopped hiding the problem. Do not re-litigate the watchdog here.

Anima work item `019fb9d7-395c-74b0-8f91-7bfcef1bf03b`. ## What happened Session `019fb977-d7ff-70f3-b89f-d15f18566c65`, workspace `tecton`, WI-259, on image `0fc0416b257d` (post-#279): ``` 18:37:46 session.started 18:40:53 ONE agent_thought — "Let me start by understanding the current state…" … 57 minutes, nothing 19:38:00 agent_message, 1423 chars, ending "Let me now examine the actual code…" 19:38:00 turn_completed {"outcome":"failed","stop_reason":"cancelled", "error_text":"turn killed by the 3600s budget cap — the agent produced no durable output"} ``` The agent had understood its task correctly — it read the review verdict and enumerated the 15-file blast radius back accurately. It then produced **1423 characters in 57 minutes** and nothing durable. ## Why the existing signals cannot explain it Both supervision mechanisms stayed silent, and each silence is informative: - **Idle watchdog: never fired.** `grep -c "chat turn stalled"` = 0. #279's heartbeat did its job — this is no longer a false kill. - **Socket read timeout (`AKH_SOCKET_READ_TIMEOUT_SECS`, default 60s): never fired.** So **bytes were arriving on the socket at least every 60 seconds for the entire hour.** The connection was alive and the provider was delivering. So this is neither a hang nor a dead socket. Something was being received, continuously, and almost none of it became work. We currently have no way to say what. Until #279 landed, the watchdog killed these turns at 2700s and mislabelled them `empty`, so the question could not even be asked. ## What to instrument Per LLM request, at completion (and on cancellation), one structured log line: - `chunks_received`, `bytes_received` - counts by kind: content deltas, thinking deltas, tool-call chunks, keepalive-only chunks (a chunk that yielded no visible event) - `prompt_eval_count` / `eval_count` from Ollama's final message, and wall duration - `request_seq` within the turn, so a turn that issues 40 requests is distinguishable from one that issues a single 57-minute request That single line separates the live hypotheses, which today we cannot choose between: 1. **one enormous slow generation** — few requests, high `eval_count`, steady bytes 2. **a retry/roundtrip loop** — many requests, low `eval_count` each 3. **thinking that never converges** — `thinking` deltas dominate, `content` and `tool_calls` near zero (note `reasoning_effort = "high"` is set on tecton and the model advertises a 1,000,000-token context window) 4. **received-but-discarded** — bytes arrive, nothing parses into an event ## Also worth capturing - Log the **prompt size** actually sent. A 1M context window plus a large repo brief may be producing pathological latency; right now nobody can see the input size at all. - Emit the same counters on the cancellation path, not just clean completion — the interesting turns are the ones that get killed. ## Acceptance - One structured line per LLM request carrying the counters above, present on both the completed and cancelled paths. - Re-running the WI-259 turn shape yields a log that identifies which of the four hypotheses holds. - The counters are cheap enough to leave on permanently (counters and one line per request, not per chunk). ## Context Related: WI-271 (the heartbeat, merged as #279) — this item exists *because* that fix worked and stopped hiding the problem. Do not re-litigate the watchdog here.

toasterson added 1 commit 2026-07-31 20:49:53 +00:00

A turn can receive bytes for 57 minutes and produce nothing — instrument per-request chunks, bytes and tokens so "generating slowly" is distinguishable from "receiving nothing useful" ... 141978e9dc

Anima implementation session.

toasterson changed title from WIP: A turn can receive bytes for 57 minutes and produce nothing — instrument per-request chunks, bytes and tokens so "generating slowly" is distinguishable from "receiving nothing useful" to A turn can receive bytes for 57 minutes and produce nothing — instrument per-request chunks, bytes and tokens so "generating slowly" is distinguishable from "receiving nothing useful" 2026-07-31 21:26:06 +00:00

toasterson merged commit a324a45434 into main 2026-07-31 21:44:20 +00:00

toasterson referenced this pull request from a commit 2026-07-31 21:44:21 +00:00

Merge pull request #280: Per-request LLM metrics — chunks, bytes, deltas by kind, tokens, prompt size

Sign in to join this conversation.

Reviewers

No reviewers

Labels

Clear labels

No items

No labels

Milestone

Clear milestone

No items

No milestone

Projects

Clear projects

No items

No project

Assignees

Clear assignees

No assignees

1 participant

Notifications

Subscribe

Due date

The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set

Reference

toasterson/akh-medu!280

No description provided.