coilyco-gaming/sirens-echo

Watch

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

New issue

Closed

opened 2026-08-18 01:21:05 +00:00 by coilyco-ops · 7 comments

coilyco-ops commented

2026-08-18 01:21:05 +00:00

Member

Filed by Olaf (ops seat) after Kai reported that Owl Deep took heavy load over roughly an hour and performed badly. Treated as a critical failure.

Proceeds under the #929 amendment recorded 2026-08-18: everything proposed here changes only how well the lane does what it already does, so none of it is a frozen feature.

Summary

sirens-deep-owl-glass is not slow because something broke. It is slow because every turn ships roughly 116 KB of fixed prompt through a flash-tier model with prompt caching returning zero cache hits for the whole burst, then loops that payload five to eight times per reply.

The load did not cause this. The load exposed it.

Window and volume

Burst ran 00:25 to 01:10 UTC, 2026-08-18. Nine turns in the owl lane.

9 turns produced 53 model calls and 60 MCP tool calls
over the wider 2h window: 84 model calls, 2,419,980 input tokens, averaging 28,809 tokens per call
total cost across those 2 hours: $0.101

Cost is why this went unnoticed. It is a latency and quality failure, not a spend one.

Latency, owl lane against the plain Deep lane

community.turn p50 - 32.9s owl // 8.7s sirens-deep - 3.8x
model.chat p95 - 33.2s owl // 13.5s sirens-deep
service p99 - 182.6s, sitting on the 180s ceiling already recorded in #577
worst single turn - accepted 00:47:42, delivered 00:50:45, 3m03s
error rate - 5 of 215 calls, 2.3%

Three error signatures, all from spans on the lane:

Agent Proxy response exceeded the size limit. on model.chat, whose child HTTP POST to ser8:8080/v1/chat/completions returns HTTP 200 and then fails with context deadline exceeded
An MCP tool reported its own call as failed.
Turn processing failed., bubbling all the way to discord.receive

Root cause chain

1. The fixed prefix is enormous and paid on every call

Constant across every request measured:

system_prompt_bytes - 61,142
tool block at 86 tools - 57,347 bytes
fixed overhead before any user content - ~116 KB

A 977-byte user question produced a 127,222-byte request. That is 99.2% overhead.

2. Prompt caching went dark. This is the decisive finding.

spans carrying gen_ai.usage.cache_read_input_tokens in the incident 2h window - 0
same over 24h - 252 spans, 6,109,440 tokens

Caching demonstrably works on this stack and delivered nothing during the burst. Two obvious explanations are ruled out:

Not a model or route change. deepseek-v4-flash via sirens-echo/deepseek, stable across all 24h with no other model on the lane.
Not an unstable prefix. The tool block is byte-exact per tool count - min equals max at 86 → 57,347, 67 → 48,467, 82 → 43,116.

So 84 calls each re-paid full freight on a ~29k-token prefix that was supposed to be cached. This is the single biggest lever on the 32.9s median.

Not yet established: why. That needs a direct look at agent-proxy and LiteLLM cache configuration, which I have not opened. Related to #162, which covers caching as a cost lever rather than as a regression.

3. Tool-round amplification multiplies both

Within one trace, request_bytes climbed 128,443 → 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.

The owl lane carries 86 tools against the plain lane's 67. The extra 19 are the Discord write surface, and they sit on the prefix that stopped being cached.

Quality failures, all from the runtime record

The "didn't do a good job" half is not vague. Six distinct failures:

Hallucination. model.response.repair fired with refused: "model claimed an action the runtime has not performed". The guard caught it, then spent two more rounds recovering.
A false error shown to a member. One turn delivered a 90-byte model backend unavailable, retry shortly notice, with model.response status: 200 logged one second earlier. A member was told the backend was down when it had answered.
Blind retry of a known-dead tool. browser_navigate failed twice with byte-identical 30-byte input before the model gave up. Playwright has been permanently dead since the session-recovery bug in #897 and coilyco-flight-deck/mcp-beaver#80. Deep does not know that and burns rounds rediscovering it every turn.
Redundant over-fetching. Two near-identical forgejo list_issue calls back to back, both over the 16,384-byte cap, dropping 403 and 1,677 bytes after paying to retrieve them.
Reasoning budget blowout. model.budget.raised with 15,036 bytes of reasoning against a 7,200 max_tokens ceiling, forcing a retry.
Progress spam. One 3-minute turn produced 1 post, 10 edits and 1 delete. Twelve Discord write operations for one reply, roughly one every 16 seconds.

The response.validate spans all passed clean, so the validation layer is not catching any of this. It is upstream of validation.

Reproduced live while writing this

Two turn calls into the lane at ~01:15 UTC, both read-only:

first returned The operation timed out.
second returned the canned > busy, retry shortly

Same class of notice a member received at 00:43. The lane is still in this state.

Ruled out

Host pressure. ser8 is idle. CPU 1.1%, memory 15.1%, load average 2.27. Nothing is starved.
Cost. $0.101 per 2h. Not a spend problem.

What is new here vs already tracked

Already filed, and this issue corroborates rather than duplicates:

#577 - p99 turn on the 180s ceiling
#367 - 43% silent-failure rate at the completion ceiling
#897 and coilyco-flight-deck/mcp-beaver#80 - playwright permanently dead after session recovery fails
#162 - prompt caching as a cost lever
#859 - skillpack inlined into every prompt (closed 2026-08-17)

New and not recorded anywhere I could find: caching produced zero cache reads during the burst against 6.1M over the day, with no model change and no prefix instability to explain it.

Why this is demo-critical

The owl.glass lane is the August 19 Temporal Vibe Check lane, roughly 34 hours out at filing. Kai's contracted deliverable is an agent staged in a shared Discord interacting with other participants' agents, on a permanent public recording.

What was measured is that lane, under live load, taking 33s at the median and 3 minutes at the tail, hallucinating an action, and telling a member the backend was down when it was not.

#929 names #335 (cached trajectories, Ornith warm, cutover trigger) as the only dead-air mitigation, and this is the failure it was written against.

Proposed work, cheapest and highest-leverage first

Find why cache reads went to zero and restore them. Agent-proxy and LiteLLM cache configuration. Highest leverage by a wide margin and no behaviour change.
Drop playwright and bluesky from the owl roster until mcp-beaver#80 lands. They cannot succeed, and they cost rounds and prefix bytes on every turn.
Cap tool rounds on the Discord transport so a turn cannot reach round 7 plus nested sub-turns.
Throttle progress edits. Twelve Discord writes per reply is rate-limit-adjacent and reads as thrashing.
Raise max_tokens above the observed reasoning envelope, or stop paying for a repair round on every budget overrun.

Items 2 through 5 are harness changes and belong to Engineering. Item 1 is agent-proxy configuration.

Done when

The owl lane's community.turn p50 is back in the same order as sirens-deep's 8.7s, cache reads are non-zero on the lane, and no member-facing turn reports a backend failure on an HTTP 200.

Gaps in this report, stated rather than papered over

I have no Discord message text. The read-only discord MCP returns 403 Missing Access on #engineering. Two proxied read attempts through the owl lane's own turn tool failed, as recorded above. Reply sizes and runtime events are measured, reply wording is not.
I did not open agent-proxy or LiteLLM configuration. The caching claim is a measurement of behaviour, not a reading of config. Cause is inference until someone opens it.

**Filed by Olaf (ops seat)** after Kai reported that Owl Deep took heavy load over roughly an hour and performed badly. Treated as a critical failure. Proceeds under the [#929 amendment](https://forgejo.coilysiren.me/coilyco-gaming/sirens-echo/issues/929) recorded 2026-08-18: everything proposed here changes only how well the lane does what it already does, so none of it is a frozen feature. ## Summary `sirens-deep-owl-glass` is not slow because something broke. It is slow because every turn ships roughly **116 KB of fixed prompt** through a flash-tier model with **prompt caching returning zero cache hits for the whole burst**, then loops that payload five to eight times per reply. The load did not cause this. The load exposed it. ## Window and volume Burst ran **00:25 to 01:10 UTC, 2026-08-18**. Nine turns in the owl lane. * 9 turns produced **53 model calls** and **60 MCP tool calls** * over the wider 2h window: **84 model calls**, **2,419,980 input tokens**, averaging **28,809 tokens per call** * total cost across those 2 hours: **$0.101** Cost is why this went unnoticed. It is a latency and quality failure, not a spend one. ## Latency, owl lane against the plain Deep lane * `community.turn` p50 - **32.9s** owl // **8.7s** `sirens-deep` - 3.8x * `model.chat` p95 - **33.2s** owl // **13.5s** `sirens-deep` * service p99 - **182.6s**, sitting on the 180s ceiling already recorded in #577 * worst single turn - accepted 00:47:42, delivered 00:50:45, **3m03s** * error rate - 5 of 215 calls, **2.3%** Three error signatures, all from spans on the lane: * `Agent Proxy response exceeded the size limit.` on `model.chat`, whose child `HTTP POST` to `ser8:8080/v1/chat/completions` returns **HTTP 200** and then fails with `context deadline exceeded` * `An MCP tool reported its own call as failed.` * `Turn processing failed.`, bubbling all the way to `discord.receive` ## Root cause chain ### 1. The fixed prefix is enormous and paid on every call Constant across every request measured: * `system_prompt_bytes` - **61,142** * tool block at 86 tools - **57,347 bytes** * fixed overhead before any user content - **~116 KB** A **977-byte** user question produced a **127,222-byte** request. That is **99.2% overhead**. ### 2. Prompt caching went dark. This is the decisive finding. * spans carrying `gen_ai.usage.cache_read_input_tokens` in the incident 2h window - **0** * same over 24h - **252 spans, 6,109,440 tokens** Caching demonstrably works on this stack and delivered **nothing** during the burst. Two obvious explanations are ruled out: * **Not a model or route change.** `deepseek-v4-flash` via `sirens-echo/deepseek`, stable across all 24h with no other model on the lane. * **Not an unstable prefix.** The tool block is byte-exact per tool count - min equals max at 86 → 57,347, 67 → 48,467, 82 → 43,116. So 84 calls each re-paid full freight on a ~29k-token prefix that was supposed to be cached. This is the single biggest lever on the 32.9s median. **Not yet established:** why. That needs a direct look at agent-proxy and LiteLLM cache configuration, which I have not opened. Related to #162, which covers caching as a cost lever rather than as a regression. ### 3. Tool-round amplification multiplies both Within one trace, `request_bytes` climbed **128,443 → 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**. The owl lane carries **86 tools** against the plain lane's **67**. The extra 19 are the Discord write surface, and they sit on the prefix that stopped being cached. ## Quality failures, all from the runtime record The "didn't do a good job" half is not vague. Six distinct failures: * **Hallucination.** `model.response.repair` fired with `refused: "model claimed an action the runtime has not performed"`. The guard caught it, then spent two more rounds recovering. * **A false error shown to a member.** One turn delivered a 90-byte `model backend unavailable, retry shortly` notice, with `model.response status: 200` logged **one second earlier**. A member was told the backend was down when it had answered. * **Blind retry of a known-dead tool.** `browser_navigate` failed twice with byte-identical 30-byte input before the model gave up. Playwright has been permanently dead since the session-recovery bug in #897 and coilyco-flight-deck/mcp-beaver#80. Deep does not know that and burns rounds rediscovering it every turn. * **Redundant over-fetching.** Two near-identical `forgejo list_issue` calls back to back, both over the 16,384-byte cap, dropping 403 and 1,677 bytes after paying to retrieve them. * **Reasoning budget blowout.** `model.budget.raised` with **15,036 bytes of reasoning against a 7,200 `max_tokens` ceiling**, forcing a retry. * **Progress spam.** One 3-minute turn produced 1 post, 10 edits and 1 delete. **Twelve Discord write operations for one reply**, roughly one every 16 seconds. The `response.validate` spans all passed clean, so the validation layer is not catching any of this. It is upstream of validation. ## Reproduced live while writing this Two `turn` calls into the lane at ~01:15 UTC, both read-only: 1. first returned **`The operation timed out.`** 2. second returned the canned **`> busy, retry shortly`** Same class of notice a member received at 00:43. The lane is still in this state. ## Ruled out * **Host pressure.** ser8 is idle. CPU **1.1%**, memory **15.1%**, load average **2.27**. Nothing is starved. * **Cost.** $0.101 per 2h. Not a spend problem. ## What is new here vs already tracked Already filed, and this issue corroborates rather than duplicates: * #577 - p99 turn on the 180s ceiling * #367 - 43% silent-failure rate at the completion ceiling * #897 and coilyco-flight-deck/mcp-beaver#80 - playwright permanently dead after session recovery fails * #162 - prompt caching as a cost lever * #859 - skillpack inlined into every prompt (closed 2026-08-17) **New and not recorded anywhere I could find:** caching produced **zero** cache reads during the burst against 6.1M over the day, with no model change and no prefix instability to explain it. ## Why this is demo-critical The owl.glass lane is the **August 19 Temporal Vibe Check** lane, roughly 34 hours out at filing. Kai's contracted deliverable is an agent staged in a shared Discord interacting with other participants' agents, on a permanent public recording. What was measured is that lane, under live load, taking 33s at the median and 3 minutes at the tail, hallucinating an action, and telling a member the backend was down when it was not. #929 names #335 (cached trajectories, Ornith warm, cutover trigger) as the only dead-air mitigation, and this is the failure it was written against. ## Proposed work, cheapest and highest-leverage first 1. **Find why cache reads went to zero** and restore them. Agent-proxy and LiteLLM cache configuration. Highest leverage by a wide margin and no behaviour change. 2. **Drop playwright and bluesky from the owl roster** until mcp-beaver#80 lands. They cannot succeed, and they cost rounds and prefix bytes on every turn. 3. **Cap tool rounds** on the Discord transport so a turn cannot reach round 7 plus nested sub-turns. 4. **Throttle progress edits.** Twelve Discord writes per reply is rate-limit-adjacent and reads as thrashing. 5. **Raise `max_tokens` above the observed reasoning envelope**, or stop paying for a repair round on every budget overrun. Items 2 through 5 are harness changes and belong to Engineering. Item 1 is agent-proxy configuration. ## Done when The owl lane's `community.turn` p50 is back in the same order as `sirens-deep`'s 8.7s, cache reads are non-zero on the lane, and no member-facing turn reports a backend failure on an HTTP 200. ## Gaps in this report, stated rather than papered over * **I have no Discord message text.** The read-only discord MCP returns `403 Missing Access` on `#engineering`. Two proxied read attempts through the owl lane's own `turn` tool failed, as recorded above. Reply sizes and runtime events are measured, reply wording is not. * **I did not open agent-proxy or LiteLLM configuration.** The caching claim is a measurement of behaviour, not a reading of config. Cause is inference until someone opens it.

coilyco-ops added the

labels

2026-08-18 01:21:05 +00:00

coilyco-ops commented

2026-08-18 01:24:36 +00:00

Author

Member

Follow-up: a controlled reproduction, and a correction to the issue body

Kai asked me to read the Discord side through Owl Deep's own server rather than the read-only discord MCP. Doing that produced better evidence than the original telemetry, and corrected one thing I got wrong.

Correction: the channel was not Sirens `#engineering`

The issue body says I could not read #engineering. That framing was wrong. This lane's Discord tools are scoped to the owl.glass guild, not Sirens:

discord.get_owl-glass-guild
discord.get_current-user
discord.mcp_beaver_info

I had inferred #engineering from Discord snowflake IDs falling in a similar range, which is worthless as evidence because snowflakes are global rather than per-guild. The burst was on owl.glass.

The lane cannot read Discord messages at all

Asked directly, Deep answered:

My Discord tools cannot list the owl.glass guild's channels (no channel enumeration endpoint is exposed, and the guild lookup returns none), so I cannot determine which channels I replied in during the last hour and cannot produce either requested report.

So the grant is guild and user metadata only. No channel enumeration, no message listing. A proxied read is not possible with the current guardfile, and no reply text can be recovered from either side.

Widening that grant would be a new capability, so it is a frozen feature under #929 and is not proposed here. Noting it only so nobody repeats the attempt.

The controlled experiment, and the real quality failure

Four turns into the lane, same tools, same prefix. The only variable was how tightly the request was bounded.

Unconstrained ("read back the exchange and report") - community.turn 163.3s, then 140.0s. Both exceeded the client timeout and returned nothing to the caller.
Loosely constrained ("list the last 10 messages, nothing else") - 69.0s, returned 595 bytes.
Hard constrained ("if your tools cannot do this, say exactly that in one sentence and stop, do not substitute another tool") - 52.2s, correct one-sentence refusal, 4 tool calls.

What the two long runs actually did, from the span record: asked to list Discord messages, Deep called get_owl-glass-guild, then spiralled through scratch_search, scratch_list, scratch_read, fetch_url, forgejo list_issue, mcp_beaver_info and refresh_tools across rounds 0 through 14, with request_bytes climbing 123,160 → 231,246. It never called a message-listing tool, because none exists.

This is the root of the quality complaint, and it is not the prompt size. The harness does not fail on missing capability. It fails to recognise missing capability, then substitutes unrelated tools and burns the round budget manufacturing a plausible-looking answer. The 1,849-byte reply the first long run eventually produced was assembled from scratchpad and fetch results that had nothing to do with what was asked.

That behaviour reproduced three times out of three under an unconstrained prompt, and stopped immediately when the prompt named the refusal as an acceptable outcome.

A clean measurement of the prefix tax

The hard-constrained run is the useful number. Four trivial Discord metadata calls, a one-sentence answer, an idle host, and it still took 52.2 seconds.

That is close to a floor for this lane in its current state, and it isolates the uncached ~116 KB prefix from every other variable. Round capping alone will not get this lane to a usable latency. The caching regression in the issue body has to be fixed first.

Additions to the proposed work

Slotting in ahead of the existing items 3 through 5:

Teach the model to decline on missing capability. When no tool can serve the request, the correct turn is one round and a refusal. Today it is fifteen rounds and a confabulation. This is the highest-value quality fix and it needs no new grant.
Bound tool substitution. A request naming one server should not silently satisfy itself from three unrelated ones.

Both are harness behaviour changes on existing capability, so both sit on the operational-improvement side of the #929 amendment.

## Follow-up: a controlled reproduction, and a correction to the issue body Kai asked me to read the Discord side through Owl Deep's own server rather than the read-only discord MCP. Doing that produced better evidence than the original telemetry, and corrected one thing I got wrong. ### Correction: the channel was not Sirens `#engineering` The issue body says I could not read `#engineering`. That framing was wrong. This lane's Discord tools are scoped to the **owl.glass guild**, not Sirens: ``` discord.get_owl-glass-guild discord.get_current-user discord.mcp_beaver_info ``` I had inferred `#engineering` from Discord snowflake IDs falling in a similar range, which is worthless as evidence because snowflakes are global rather than per-guild. The burst was on owl.glass. ### The lane cannot read Discord messages at all Asked directly, Deep answered: > My Discord tools cannot list the owl.glass guild's channels (no channel enumeration endpoint is exposed, and the guild lookup returns none), so I cannot determine which channels I replied in during the last hour and cannot produce either requested report. So the grant is **guild and user metadata only**. No channel enumeration, no message listing. A proxied read is not possible with the current guardfile, and no reply text can be recovered from either side. **Widening that grant would be a new capability, so it is a frozen feature under #929 and is not proposed here.** Noting it only so nobody repeats the attempt. ### The controlled experiment, and the real quality failure Four turns into the lane, same tools, same prefix. The only variable was how tightly the request was bounded. * **Unconstrained** ("read back the exchange and report") - `community.turn` **163.3s**, then **140.0s**. Both exceeded the client timeout and returned nothing to the caller. * **Loosely constrained** ("list the last 10 messages, nothing else") - **69.0s**, returned 595 bytes. * **Hard constrained** ("if your tools cannot do this, say exactly that in one sentence and stop, do not substitute another tool") - **52.2s**, correct one-sentence refusal, 4 tool calls. What the two long runs actually did, from the span record: asked to list Discord messages, Deep called `get_owl-glass-guild`, then spiralled through `scratch_search`, `scratch_list`, `scratch_read`, `fetch_url`, `forgejo list_issue`, `mcp_beaver_info` and `refresh_tools` across **rounds 0 through 14**, with `request_bytes` climbing **123,160 → 231,246**. It never called a message-listing tool, because none exists. **This is the root of the quality complaint, and it is not the prompt size.** The harness does not fail on missing capability. It fails to *recognise* missing capability, then substitutes unrelated tools and burns the round budget manufacturing a plausible-looking answer. The 1,849-byte reply the first long run eventually produced was assembled from scratchpad and fetch results that had nothing to do with what was asked. That behaviour reproduced **three times out of three** under an unconstrained prompt, and stopped immediately when the prompt named the refusal as an acceptable outcome. ### A clean measurement of the prefix tax The hard-constrained run is the useful number. Four trivial Discord metadata calls, a one-sentence answer, an idle host, and it still took **52.2 seconds**. That is close to a floor for this lane in its current state, and it isolates the uncached ~116 KB prefix from every other variable. Round capping alone will not get this lane to a usable latency. The caching regression in the issue body has to be fixed first. ### Additions to the proposed work Slotting in ahead of the existing items 3 through 5: * **Teach the model to decline on missing capability.** When no tool can serve the request, the correct turn is one round and a refusal. Today it is fifteen rounds and a confabulation. This is the highest-value quality fix and it needs no new grant. * **Bound tool substitution.** A request naming one server should not silently satisfy itself from three unrelated ones. Both are harness behaviour changes on existing capability, so both sit on the operational-improvement side of the #929 amendment.

Rows
Columns

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

Summary

Window and volume

Latency, owl lane against the plain Deep lane

Root cause chain

1. The fixed prefix is enormous and paid on every call

2. Prompt caching went dark. This is the decisive finding.

3. Tool-round amplification multiplies both

Quality failures, all from the runtime record

Reproduced live while writing this

Ruled out

What is new here vs already tracked

Why this is demo-critical

Proposed work, cheapest and highest-leverage first

Done when

Gaps in this report, stated rather than papered over

Follow-up: a controlled reproduction, and a correction to the issue body

Correction: the channel was not Sirens #engineering

The lane cannot read Discord messages at all

The controlled experiment, and the real quality failure

A clean measurement of the prefix tax

Additions to the proposed work

Rejected

Approved, and where each already lives

Approved but already fixed, correcting my own earlier claim

Verified after-state

One thing worth recording for the next operator

The measurement

Why the attribute is absent, from the source

What that does to the issue

Proposed next step, smallest first

Landed

Split out

Where that leaves #932

Correction: the channel was not Sirens `#engineering`