coilyco-gaming/sirens-echo

Watch

Measure where the 32.9s turn actually goes: a 116 KB prefix paid roughly six times per reply #1002

New issue

Closed

opened 2026-08-19 00:56:01 +00:00 by coilyco-ops · 3 comments

coilyco-ops commented

2026-08-19 00:56:01 +00:00

Member

Split out of #932. With that issue's caching explanation withdrawn, this is the surviving mechanical explanation of the 32.9s median, and it needs no proxy change to investigate.

The arithmetic

Every number here is from #932's own measurements and none of them depended on the cache claim:

Fixed overhead before any user content - ~116 KB, from a 61,142 byte system prompt and a 57,347 byte tool block at 86 tools
A 977 byte user question produced a 127,222 byte request. 99.2% overhead
Within one trace, request_bytes climbed 128,443 to 217,079 across rounds 0 through 5, plus three nested sub-turns
Roughly 5.9 model calls and 6.7 tool calls per single Discord reply
community.turn p50 - 32.9s on this lane against 8.7s on plain sirens-deep

So the prefix is not paid once per reply. It is paid about six times, and it grows as the round's history accumulates.

At 5.9 calls averaging even 5s of model time, the median is accounted for without any cache behaviour entering the explanation. That is the thing to confirm or refute.

What to establish first

Where the 32.9s actually goes. Break one median turn into its parts: time in model calls, time in tool calls, time in the harness between them. #932 reports model.chat p95 at 33.2s on this lane against 13.5s on sirens-deep, which suggests the individual calls are slow rather than merely numerous, but the per-turn split has not been measured.

That single breakdown decides which lever matters:

If the time is in the calls, the prefix size is the lever and the question is what makes a 29k-token prompt take that long on a flash-tier model.
If the time is in the count, the round trips are the lever and the question is why a reply needs six.
If the time is between them, it is harness overhead and neither.

Getting that wrong is what this issue exists to prevent. #932 spent its analysis on a cache regression that turned out to be a reporting artifact, so the discipline here is to measure the split before proposing anything.

Constraints that already apply

Kai rejected cutting the roster from 86 tools, in her words "no, we fix the servers", recorded on #932. Proposal 2 there is closed by decision. Do not re-propose a narrower roster as a latency fix. Bluesky was separately deprovisioned, taking both Sirens harnesses from 12 MCP servers to 11, so the current tool count should be re-measured rather than assumed to still be 86.

The freeze. Under the #929 amendment, work that changes only how well the lane does what it already does is not frozen. A change that moves capability is.

#932 - the parent, and the correction that produced this split
coilyco-flight-deck/agent-proxy#138 - the measurement gap that made the cache lever unreadable, fixed in 50af3de. Once that rolls out, the cache hit rate becomes a real number and can be ruled in or out properly rather than by inference
#162 - caching as a cost lever rather than a regression
#897 and coilyco-flight-deck/mcp-beaver#80 - the dead-server session recovery that keeps the roster paying for tools that are not answering

Split out of #932. With that issue's caching explanation withdrawn, this is the surviving mechanical explanation of the 32.9s median, and it needs no proxy change to investigate. ## The arithmetic Every number here is from #932's own measurements and none of them depended on the cache claim: * Fixed overhead before any user content - **~116 KB**, from a **61,142** byte system prompt and a **57,347** byte tool block at 86 tools * A **977** byte user question produced a **127,222** byte request. **99.2% overhead** * Within one trace, `request_bytes` climbed **128,443 to 217,079** across rounds 0 through 5, plus three nested sub-turns * Roughly **5.9 model calls and 6.7 tool calls per single Discord reply** * `community.turn` p50 - **32.9s** on this lane against **8.7s** on plain `sirens-deep` So the prefix is not paid once per reply. It is paid about six times, and it grows as the round's history accumulates. At 5.9 calls averaging even 5s of model time, the median is accounted for without any cache behaviour entering the explanation. That is the thing to confirm or refute. ## What to establish first **Where the 32.9s actually goes.** Break one median turn into its parts: time in model calls, time in tool calls, time in the harness between them. #932 reports `model.chat` p95 at 33.2s on this lane against 13.5s on `sirens-deep`, which suggests the individual calls are slow rather than merely numerous, but the per-turn split has not been measured. That single breakdown decides which lever matters: * If the time is **in the calls**, the prefix size is the lever and the question is what makes a 29k-token prompt take that long on a flash-tier model. * If the time is **in the count**, the round trips are the lever and the question is why a reply needs six. * If the time is **between them**, it is harness overhead and neither. Getting that wrong is what this issue exists to prevent. #932 spent its analysis on a cache regression that turned out to be a reporting artifact, so the discipline here is to measure the split before proposing anything. ## Constraints that already apply **Kai rejected cutting the roster from 86 tools**, in her words *"no, we fix the servers"*, recorded on #932. Proposal 2 there is closed by decision. Do not re-propose a narrower roster as a latency fix. Bluesky was separately deprovisioned, taking both Sirens harnesses from 12 MCP servers to 11, so the current tool count should be re-measured rather than assumed to still be 86. **The freeze.** Under the [#929 amendment](https://forgejo.coilysiren.me/coilyco-gaming/sirens-echo/issues/929), work that changes only how well the lane does what it already does is not frozen. A change that moves capability is. ## Related * #932 - the parent, and the correction that produced this split * `coilyco-flight-deck/agent-proxy#138` - the measurement gap that made the cache lever unreadable, fixed in `50af3de`. Once that rolls out, the cache hit rate becomes a real number and can be ruled in or out properly rather than by inference * #162 - caching as a cost lever rather than a regression * #897 and `coilyco-flight-deck/mcp-beaver#80` - the dead-server session recovery that keeps the roster paying for tools that are not answering

coilyco-ops referenced this issue

2026-08-19 00:56:27 +00:00

owl.glass lane: 32.9s median turn under load, from a 116 KB prompt prefix that stopped being cached #932

coilyco-ops referenced this issue

2026-08-19 01:44:54 +00:00

Load test: Dowel refuses 3 of 8 summons at the stream's own arrival shape, each after a 50s wait for an execution slot #1010

coilyco-ops referenced this issue

2026-08-19 03:24:31 +00:00

Dowel carries no record of earlier work in a long session, and widening the prefill fights the prefix cost #1034

coilyco-ops referenced this issue

2026-08-19 03:25:23 +00:00

Measure and cut the demo lane's member-facing error rate, keeping trace IDs #1037

coilyco-ops added the

labels

2026-08-19 03:38:45 +00:00

coilyco-ops referenced this issue

2026-08-19 04:03:09 +00:00

Epic: August 19 Temporal Vibe Check demo readiness, the work that is on camera #981

coilyco-ops added this to the August 19 Temporal Vibe Check milestone

2026-08-19 04:12:51 +00:00

coilyco-ops modified the milestone from August 19 Temporal Vibe Check to August 19 morning of

2026-08-19 05:35:06 +00:00

coilyco-ops referenced this issue

2026-08-19 15:35:11 +00:00

turn-stages.md halves the settle hold: it says 10s, the cap is 20s, and telemetry says 19.9997s #1078

coilyco-ops commented

2026-08-19 15:36:30 +00:00

Author

Member

The split this issue asked for, measured

Ran while debugging sirens-dowel time-to-first-reply. This is the "break one median turn into model time, tool time, harness time" task, not a proposal. Window is 24h to 2026-08-19T15:00Z, which is a later and busier window than #932's, on a lane redeployed ten times that day.

The answer is bimodal, and that is the finding. The three-way question in this issue assumes one answer, and the lane has two populations that resolve it differently.

Ordinary turns - the harness wins, and it is the settle.

22.3s total - model 10.0s across 2 calls (45%) - tools 0.63s - settle 9.5s - harness 2.2s
35.3s total - model 12.2s across 2 calls (34%) - tools 1.12s - settle 20.0s - harness 2.0s
17.2s total - model 15.1s across 2 calls (88%) - tools 2.02s - settle 0s - harness 0s

Slow turns - the calls win, near-totally.

300.8s total - model 298.4s across 10 calls (99.2%) - tools 0.95s - settle 0s - harness ~1.4s
301.2s total - model 298.3s across 9 calls (99.0%)

So against this issue's three branches: on a median turn the time is between the calls, and it is one named span rather than diffuse overhead. On a slow turn it is in the calls, and tool time is noise at under 1% either way. Tool calls are not the lever in any population measured.

Two premises here need correcting

The median turn makes 2 model calls, not 5.9. Over 120 turns there were 446 model.chat spans, a mean of 3.7, but every median-range turn sampled made exactly 2. The mean is dragged by a tail making 9, 10, and in one case 36. So "the prefix is paid about six times" is true of the mean and false of the median, and a lever sized against six would be sized against a distribution that has no mass there.

The tool count is 63, not 86. One model.request on round 6 logged tool_count: 63 alongside request_bytes: 237083 and message_count: 21. That answers the re-measurement this issue asked for. It also puts the request at 237 KB by round 6, against the 217 KB #932 saw at round 5.

The mechanism inside a slow turn

Per-call durations within one turn, in order:

22.1s, 27.8s, 20.1s, 10.5s, 6.6s, 32.2s, 46.2s, 66.2s, 66.7s then failure on "Agent Proxy response exceeded the size limit"

and another:

22.5s, 10.6s, 3.5s, 13.0s, 29.1s, 55.1s, 55.9s, 3.2s, 61.3s, 44.2s then the same failure

The calls are not uniformly slow. They accelerate downward as rounds accumulate, roughly tripling from early rounds to late ones. So "slow calls" and "many calls" are not competing explanations here, they are the same explanation: round N is slow because rounds 1 to N-1 happened. That is consistent with prefix-plus-history growth and does not require the cache question to be settled first, though it does not rule the cache in or out either.

Three of seven turns in the 11:25 to 11:55 run ended this way against the 5m SIRENS_ECHO_REQUEST_TIMEOUT.

What I did not establish

No cache attribution. I did not check whether gen_ai.usage.cache_read_input_tokens is now populated on upstream.chat_stream, so coilyco-bridge/deploy#699's rollout question is untouched by this.
Per-round token counts. request_bytes is bytes, and the growth curve above is inferred from durations rather than from measured prompt tokens per round.
Telemetry cost is unmeasured. One 300.8s turn produced 34,081 POST /v1/chat/completions http send spans from agent-proxy, one per streamed chunk, and modelIOCapture buffers each request and response whole. Whether that costs wall-clock is inference from config, not something I measured, and isolating it needs agent-proxy internal timings. Flagging it because it is a large number sitting next to a latency investigation, not because I am claiming it matters.
One lane, one day. Nothing here is checked against sirens-echo or sirens-deep, so lane-specific and harness-wide causes are not separated.

Where the harness half of this went

The settle share on median turns is being addressed from the deployment side at coilyco-bridge/deploy#740, which sets SIRENS_ECHO_PROGRESS_AFTER to 5s and halves the hold ceiling to 10s. That is a knob change and not a fix to this issue: the hold still exists, and whether holding a finished answer to protect a line that gets deleted is the right trade is open at #1078 and in the turn-stages prose.

The call-side half is untouched and is where the minutes are. Nothing above proposes a lever for it, per this issue's own discipline.

## The split this issue asked for, measured Ran while debugging sirens-dowel time-to-first-reply. This is the "break one median turn into model time, tool time, harness time" task, not a proposal. Window is 24h to 2026-08-19T15:00Z, which is a later and busier window than #932's, on a lane redeployed ten times that day. **The answer is bimodal, and that is the finding.** The three-way question in this issue assumes one answer, and the lane has two populations that resolve it differently. **Ordinary turns - the harness wins, and it is the settle.** * 22.3s total - model **10.0s** across 2 calls (45%) - tools 0.63s - settle **9.5s** - harness 2.2s * 35.3s total - model **12.2s** across 2 calls (34%) - tools 1.12s - settle **20.0s** - harness 2.0s * 17.2s total - model **15.1s** across 2 calls (88%) - tools 2.02s - settle 0s - harness 0s **Slow turns - the calls win, near-totally.** * 300.8s total - model **298.4s** across 10 calls (**99.2%**) - tools 0.95s - settle 0s - harness ~1.4s * 301.2s total - model **298.3s** across 9 calls (**99.0%**) So against this issue's three branches: on a median turn the time is **between the calls**, and it is one named span rather than diffuse overhead. On a slow turn it is **in the calls**, and tool time is noise at under 1% either way. Tool calls are not the lever in any population measured. ## Two premises here need correcting **The median turn makes 2 model calls, not 5.9.** Over 120 turns there were 446 `model.chat` spans, a mean of 3.7, but every median-range turn sampled made exactly **2**. The mean is dragged by a tail making 9, 10, and in one case 36. So "the prefix is paid about six times" is true of the mean and false of the median, and a lever sized against six would be sized against a distribution that has no mass there. **The tool count is 63, not 86.** One `model.request` on round 6 logged `tool_count: 63` alongside `request_bytes: 237083` and `message_count: 21`. That answers the re-measurement this issue asked for. It also puts the request at 237 KB by round 6, against the 217 KB #932 saw at round 5. ## The mechanism inside a slow turn Per-call durations within one turn, in order: `22.1s, 27.8s, 20.1s, 10.5s, 6.6s, 32.2s, 46.2s, 66.2s, 66.7s` then failure on "Agent Proxy response exceeded the size limit" and another: `22.5s, 10.6s, 3.5s, 13.0s, 29.1s, 55.1s, 55.9s, 3.2s, 61.3s, 44.2s` then the same failure The calls are not uniformly slow. They **accelerate downward as rounds accumulate**, roughly tripling from early rounds to late ones. So "slow calls" and "many calls" are not competing explanations here, they are the same explanation: round N is slow because rounds 1 to N-1 happened. That is consistent with prefix-plus-history growth and does not require the cache question to be settled first, though it does not rule the cache in or out either. Three of seven turns in the 11:25 to 11:55 run ended this way against the 5m `SIRENS_ECHO_REQUEST_TIMEOUT`. ## What I did not establish * **No cache attribution.** I did not check whether `gen_ai.usage.cache_read_input_tokens` is now populated on `upstream.chat_stream`, so `coilyco-bridge/deploy#699`'s rollout question is untouched by this. * **Per-round token counts.** `request_bytes` is bytes, and the growth curve above is inferred from durations rather than from measured prompt tokens per round. * **Telemetry cost is unmeasured.** One 300.8s turn produced **34,081** `POST /v1/chat/completions http send` spans from agent-proxy, one per streamed chunk, and `modelIOCapture` buffers each request and response whole. Whether that costs wall-clock is inference from config, not something I measured, and isolating it needs agent-proxy internal timings. Flagging it because it is a large number sitting next to a latency investigation, not because I am claiming it matters. * **One lane, one day.** Nothing here is checked against `sirens-echo` or `sirens-deep`, so lane-specific and harness-wide causes are not separated. ## Where the harness half of this went The settle share on median turns is being addressed from the deployment side at `coilyco-bridge/deploy#740`, which sets `SIRENS_ECHO_PROGRESS_AFTER` to 5s and halves the hold ceiling to 10s. That is a knob change and not a fix to this issue: the hold still exists, and whether holding a finished answer to protect a line that gets deleted is the right trade is open at #1078 and in the turn-stages prose. **The call-side half is untouched and is where the minutes are.** Nothing above proposes a lever for it, per this issue's own discipline.

coilyco-ops commented

2026-08-19 16:15:23 +00:00

Author

Member

The instrument this issue would use to answer its own question is saturated and cannot represent the values it needs to measure. Found while running the #976 coalescing test on sirens-dowel. QA observed only, no live action taken.

The histogram tops out at 10 seconds

sirens_echo.coalesce.turn.duration reports p50 and p99 that look calm and are not:

echo p50 10,000 ms, p99 10,000 ms
dowel p50 9,225 ms, p99 9,694 ms
deep p50 9,000 ms, p99 9,495 ms

Those numbers are bucket boundaries, not measurements. The gauge sibling over the same test window reads coalesce.turn.duration.max = 76,021 ms, and turn.duration.max over 24h reads dowel 341,617 ms and echo 303,085 ms.

So real turns run tens of seconds to minutes, every one of them lands in the overflow bucket, and the percentile estimate clamps at the top boundary. Any percentile read off this histogram is a floor, not a value. A reader taking p99 at face value concludes the lane answers in 10 seconds when the observed maximum is 34 times that.

This matters here specifically. This issue exists to find where a 32.9s turn goes, and a histogram whose top bucket is 10s cannot see a 32.9s turn at all, let alone decompose it.

Directly measured turn durations, Discord surface

From spans during the same window, lane sirens-dowel:

community.turn A - 117.61s - trace c5a1a3f777f44525d94364fb6608465b
community.turn B - 33.56s - trace b0ba3e30e781b60622bf47e7a1790fd2

Turn B at 33.56s sits almost exactly on the 32.9s this issue is named for, and it came from an ordinary Discord message rather than a load test.

Where the time went on the third message

Recorded in full at #1010, summarised here because it bears on this issue's question. Message three arrived at 15:30:18.236 and its turn started at 15:32:10.548, 112.3 seconds later, 0.5s after the preceding turn released the per-tenant lock. Arrival to reply assembled was about 147 seconds, of which roughly 112 was waiting and 34 was working.

That is the same answer #1010 reached over HTTP, now confirmed on the gateway path: under any concurrency at all, the dominant term is queue wait rather than turn work. Three messages from one member were enough to produce it.

What I did not measure

I did not observe prompt bytes, model call counts, or cache behaviour in these turns, so this says nothing about the 116 KB prefix or the six-times figure in the title. The 117.61s turn is unexplained by anything I looked at and is worth pulling apart on its own.

Suggested order

Fixing the histogram bounds is cheap and it gates everything else here. Until the buckets cover the real range, every latency percentile on this lane reads as fine, and this issue cannot be closed with evidence because its central measurement is unrepresentable. Related but distinct from the temporality mislabel on the cumulative metrics recorded in #976.

**The instrument this issue would use to answer its own question is saturated and cannot represent the values it needs to measure.** Found while running the #976 coalescing test on `sirens-dowel`. QA observed only, no live action taken. ## The histogram tops out at 10 seconds `sirens_echo.coalesce.turn.duration` reports p50 and p99 that look calm and are not: * echo p50 **10,000 ms**, p99 **10,000 ms** * dowel p50 9,225 ms, p99 9,694 ms * deep p50 9,000 ms, p99 9,495 ms Those numbers are bucket boundaries, not measurements. The gauge sibling over the same test window reads `coalesce.turn.duration.max` = **76,021 ms**, and `turn.duration.max` over 24h reads dowel **341,617 ms** and echo **303,085 ms**. So real turns run tens of seconds to minutes, every one of them lands in the overflow bucket, and the percentile estimate clamps at the top boundary. **Any percentile read off this histogram is a floor, not a value.** A reader taking p99 at face value concludes the lane answers in 10 seconds when the observed maximum is 34 times that. This matters here specifically. This issue exists to find where a 32.9s turn goes, and a histogram whose top bucket is 10s cannot see a 32.9s turn at all, let alone decompose it. ## Directly measured turn durations, Discord surface From spans during the same window, lane `sirens-dowel`: * `community.turn` A - **117.61s** - trace `c5a1a3f777f44525d94364fb6608465b` * `community.turn` B - **33.56s** - trace `b0ba3e30e781b60622bf47e7a1790fd2` Turn B at 33.56s sits almost exactly on the 32.9s this issue is named for, and it came from an ordinary Discord message rather than a load test. ## Where the time went on the third message Recorded in full at #1010, summarised here because it bears on this issue's question. Message three arrived at 15:30:18.236 and its turn started at 15:32:10.548, **112.3 seconds later**, 0.5s after the preceding turn released the per-tenant lock. Arrival to reply assembled was about 147 seconds, of which roughly 112 was waiting and 34 was working. That is the same answer #1010 reached over HTTP, now confirmed on the gateway path: **under any concurrency at all, the dominant term is queue wait rather than turn work.** Three messages from one member were enough to produce it. ## What I did not measure I did not observe prompt bytes, model call counts, or cache behaviour in these turns, so this says nothing about the 116 KB prefix or the six-times figure in the title. The 117.61s turn is unexplained by anything I looked at and is worth pulling apart on its own. ## Suggested order Fixing the histogram bounds is cheap and it gates everything else here. Until the buckets cover the real range, every latency percentile on this lane reads as fine, and this issue cannot be closed with evidence because its central measurement is unrepresentable. Related but distinct from the temporality mislabel on the cumulative metrics recorded in #976.

coilyco-ops referenced this issue

2026-08-22 20:42:01 +00:00

Carry-forward: performance and reliability findings measured during the August 19 demo, preserved after the readiness P0s closed #1094

coilyco-ops commented

2026-08-22 20:42:15 +00:00

Author

Member

Closing as delivered with the August 19 demo readiness epic (#981).

The finding here is a harness property, not a demo property: a 116 KB prefix paid roughly six times per reply inside a 32.9s turn. Preserved in #1094 so it can be re-ranked against the next forcing event on its own merits.

Decision recorded in coilysiren/inbox#391.

Closing as delivered with the August 19 demo readiness epic (#981). The finding here is a harness property, not a demo property: a 116 KB prefix paid roughly six times per reply inside a 32.9s turn. Preserved in #1094 so it can be re-ranked against the next forcing event on its own merits. Decision recorded in coilysiren/inbox#391.

coilyco-ops referenced this issue

2026-08-22 20:42:17 +00:00

Dowel's skill root opts out of progressive disclosure entirely: all six references are inline, 24KB every turn #993

coilyco-ops closed this issue

2026-08-22 20:42:29 +00:00