Repository navigation
contextmd serving: Cue misses its wait on long threads; pre-tool moments that start Cue now run out the hook deadline #248
Description
What: On rocky, in 30 minutes, Cue timed out for 1 of 21 user messages and 12 tool results, and 40 tool results came back lost because their pre-tool moment never reached serving; Cue's median round trip is 478 ms at about 1,300 window tokens.
Why: Cue's scoring time grows with the window (265 ms under 500 tokens, 480 ms at 1,500 to 3,000), long threads give long windows, and since Cue went live the pre-tool moment that starts Cue takes about twice as long, close to the hook's 1-second deadline.
So what: recommended fix is a shorter window, decided by a replay of rocky's moments at shorter windows (below); an agent implements it after the serving PRs under review (chromeria#238, #243, contextmd#51, #52) land.
Outcome
Cue scores reach the moments that need them on long threads: user-message waits and tool-result collects stop timing out at their current limits, and pre-tool moments stop missing the hook deadline, without losing the fires Cue makes today.
Problem Statement
Cue serves a rule at the moment it applies only if its score arrives in time. On rocky, where threads are long, a share of moments get no score: the user message's 650 ms wait or the tool result's 300 ms collect runs out, or the pre-tool moment that should have started the request never completes, so its tool result is lost.
Evidence (rocky, 30 minutes after Cue recovered at 16:11Z on 2026-10-13, ~/.t3/userdata/contextmd.sqlite)
| Moment | ok |
timeout |
lost |
|---|---|---|---|
| User message (waits up to 650 ms) | 20 | 1 | |
| Tool result (collects for 300 ms) | 266 | 12 | 37 (40 with a few more minutes) |
Cue time for 288 ok calls, from cue_json: round trip p50 478 ms, p90 667 ms; service time p50 425 ms, p90 527 ms; queue p50 7 ms, p90 166 ms; window tokens p50 1,326, p90 1,839. Service time by window: under 500 tokens 265 ms, 500 to 1,500 tokens 403 ms, 1,500 to 3,000 tokens 480 ms. The network is not the cost: rocky reaches bestia directly (tailscale ping 5 ms, /health about 10 ms); details on toolboxmd/contextmd#13.
What lost means: Cue.ts collect() finds no pending request for the call's key (harness, session, tool-use id). The code's comment names a restart as the cause, but here there was none: all 40 lost tool results have no pre-tool moment at all in the serving log (Claude 15, Codex 15, Grok 10; shell commands and file reads). The pre-tool moment is what starts the request, so it never started. Pruning is not the cause (pending requests live 600 s; the longest ok tool run was 272 s).
Pre-tool moments got slower with Cue (server time, which excludes hook start-up and connect): before Cue (14:00 to 15:30Z) pre-tool p50 235 ms, p90 422 ms; with Cue p50 442 ms, p90 661 ms, max 904 ms. User messages now take p50 792 ms, max 975 ms, because the 650 ms Cue wait runs inside them. The hook gives curl 1 second in total (4 s for Grok since toolboxmd/contextmd#50 is merged, once each machine pulls it). Inference, not yet verified: the missing pre-tool moments are hooks cut off at that deadline while the moment built the Cue window; the server records a moment only when it finishes.
Solution: three candidates, one recommended
- Shorter window (Router: test the input window format on the 0.6B student contextmd#20) — recommended. Window size drives both costs above: Cue's service time and the time to build the window from the projection at each moment. It is the only lever that helps all three symptoms, and it needs no retraining.
- Faster adapter (Router: a local model that matches the judge on unseen entries within one second contextmd#4). Helps service time only, and is a training effort with no date.
- Longer wait. Not available: user-message moments already take 792 ms of the hook's 1-second budget, and a longer collect lengthens every tool result; it would also do nothing for
lost.
The measurement that decides it: replay rocky's logged user-message and tool-result moments of the last day (rebuild each window from the thread projection at its moment, as the serving module does) through the Cue service at the current window and at shorter ones (for example the last 2 user messages instead of 6, and 25 items instead of 100). For each window size record service time (p50, p90) and fire agreement with the current window (same entries above threshold). Choose the shortest window whose service p90 fits the waits (under about 300 ms for collects) and whose fire agreement meets the intent-detection bar (95% of good fires, counting over- and under-firing). Separately, time window building in the pre-tool moment to confirm or refute the inference above.
Elon record
- Requirements and who asked: Cue scores at every message and tool call with latency hidden behind the tool run (user, 2026-10-12, contextmd#13); the hook fails open after 1 second (contextmd#3 design); file the long-thread timeouts with numbers, the meaning of
lost, the three fixes and a recommendation (planner, 2026-10-13). - Deleted: a longer wait (no hook budget left); the relay hypothesis (rocky's path to bestia is direct).
- Bottleneck: Cue's service time at long windows, and the pre-tool moment's time since Cue.
- Checked myself: the serving log percentiles and
cue_jsonabove;Cue.ts(WAIT_MS650,COLLECT_MS300,PENDING_SECONDS600,collect()); the 40lostcalls against the pre-tool moments and the projection; Tailscale ping and/healthtiming from rocky.
Acceptance criteria
- The replay above is run and its table (window size, service p50/p90, fire agreement) is posted here, with the chosen window.
- The pre-tool moment's time with Cue is broken down (window build vs the rest), confirming or refuting why pre-tool moments go missing.
- After the change, on rocky over one day: user-message and tool-result
timeoutandlosteach under 2% of Cue calls, and pre-tool server time p90 back near its pre-Cue 422 ms.
User stories
- As the user, I want Cue's rules to reach my agents in long threads too, so that the threads where I work longest are not the ones Cue skips.
- As the planner, I want the serving log to say why a moment got no Cue score, so that misses are fixed at their cause.
Implementation decisions
- Owned by Chromeria's serving module (
Cue.tswaits and window items,ContextmdServing.tsmoment flow). The window format itself is the Cue service's; the item limits sent are Chromeria's.
Design review
- Independent review: none yet; this Issue records the measurement first.
- User decisions: none required beyond the existing Cue decisions (contextmd#13); a window change that lowers fire agreement below the bar would need the user.
Testing decisions
- Route-level tests with the fake Cue service (as in feat(server): ContextMD's Cue lane scores every message and tool call #227) for the new item limits; the replay is the proof of latency and fire agreement.
Non-goals
- Retraining the Cue adapter (contextmd#4).
- Changing the hook deadline.
- General serving latency before Cue (chromeria#239).
Blockers
- Serving PRs in review touch the same module: chromeria#238, fix(server): command keys match what a shell command runs, not what it mentions #243 (and contextmd#51, PR panel shows "All fibers interrupted without error" when a PR link opens #52). Start after they land.
Required proof
- The replay table and the pre-tool breakdown on this Issue; one day of rocky's serving log after the change meeting the acceptance numbers.
Further notes
Related: chromeria#239 (serving moments were already 220 to 330 ms median before Cue), contextmd#53 (a Cue misfire found in the deploy check).
Canonical health incident ownership (2026-10-17)
ContextMD-Class: cue/timeout
#350 is consolidated into this Cue timeout outcome. Preserve bestia and cavallo observations in the linked consolidation comment. The existing health reporter selects the lowest-numbered open issue with this exact class line, and falls back to that search when a seeded issue is closed. Existing seed references to #248 or closed #350 therefore converge here without host configuration changes.
Activity
lukemaj commentedon Oct 13, 2026
Planner note: the hook (contextmd
bin/contextmd-hook, from ce4c4c5) usescurl --connect-timeout 0.1 -m 1. Moments that never reached the server point at the 0.1 s connect limit as much as the 1 s total limit: a request cut at 1 s would still have arrived. The timing breakdown should separate connect time from response time before choosing the fix.lukemaj commentedon Oct 13, 2026
What: No shorter window qualifies. None reaches 95% fire agreement with today's window, and none gets Cue's p90 under 300 ms.
Why: Shortening the window changes which entries fire right away (the 6,000-character budget keeps 84% of fires and adds 13 new ones), and Cue costs about 230 to 290 ms even for a near-empty window, because the instruction and the 9 entry docs are scored every time.
So what: Don't ship a shorter window for this Issue. The latency fix needs another lever (a faster adapter, contextmd#4, or a cheaper fixed part of the prompt); the planner decides which.
Result (rocky, 2026-10-13, 338 moments replayed, 95 full-window fires)
The live latency column maps each window's token count through live Cue's own service time by window size, from rocky's serving log before the replay started. The copy column is my copy's own time, measured on the same GPU while live Cue was also running, so it is noisier.
Fire agreement is kept / (full-window fires + extra fires), so it counts both under- and over-firing. The interval is 2,000 bootstrap resamples by moment. Every variant always keeps the newest message as today does (cut only past 2,500 characters when over budget). It also keeps a tool moment's call (1,000 characters) and failure output (1,000 characters). That is why tool-moment windows stay near 800 tokens at p90 even at the smallest budget.
Per entry (lost / extra against the full window):
By moment kind (agreement / live-latency p90 ms): user messages (92 moments, 30 fires) hold up best: 94% / 470 ms at 6,000 characters, then 84% / 392 at 4,000. Pre-tool moments (191, 47 fires) reach 66% / 587 at 6,000; tool failures (55, 18 fires) 65% / 601. No kind gets under 300 ms p90: user messages bottom out at 308 ms.
The latency floor: live Cue's service time under 500 window tokens is 271 ms median, and my copy measured 231 ms on a 102-token window. Shortening the window can save at most about 150 ms off today's 423 ms median.
Method
contextmd.sqliteandchromeria-v2.sqliteopenedmode=ro. Each window is rebuilt asContextmdServing.transcriptandCue.transcriptItemsdo, cut at the moment (pre-tool and failure: the items before the call's projected item; user message: up to that message). The call and failure output come from the projected tool item, since the hook payload is not stored. The order was shuffled, so the 338 finished moments are a random sample of the day.q4b-cloud-step64-w8a8c(same base, adapter, W8A8,torch.compile, threshold 0.5625), running the deployedwindow.pywithBUDGETandWORK_CHARSchanged per variant. It ran on bestia undernice 19, VRAM capped at about 6 GB, 50% GPU duty, with its own inductor cache. The live service was not touched. Scoring is deterministic: 72 identical-window pairs scored identically.ok), my rebuild matches the window size within 5 tokens on 15 and the fire set on 24. The rebuild is close to what live saw but not identical; the cause is the approximate call text and projection timing.experiment/cue-window-248(3f9f7d44f8,experiments/cue-window-248/), not for main.Limits
lukemaj commentedon Oct 13, 2026
What: after contextmd#58 went live (2 s total, 1 s connect; rocky 18:29Z, cavallo and bestia about 18:31Z), tool results with no pre-tool moment on rocky fell from about 7% to under 1%.
Why it matters: the hook's old 1 s / 0.1 s limits were what cut most of the missing pre-tool moments, not the server.
So what: the pre-tool time breakdown (this Issue's second acceptance item) continues on the new data; Chromeria is unchanged (#251 not deployed).
Rocky, from
contextmd.sqlite: a tool result or failure counts as lost when nopre_toolrow has the same harness and call id.Limits:
fix(server): Cue waits up to 1.5 s for a score the moment needs now (#…
lukemaj commentedon Oct 13, 2026
What: pre-tool time is mostly waiting for Chromeria's shared database connection, not window building, Cue or the hook's connect. That wait is what still cuts moments: since #251, 42 of 250 pre-tool moments on rocky were cut
over_budget.Why: background reads (about 1,700 orchestration events decoded per second, plus per-thread polling) keep
chromeria-v2.sqlite's single connection busy 99% of the time. Serving's queries take under 1 ms alone but queue behind that work.So what: the fix belongs to #256 (filed now), not to the Cue window. This answers the breakdown box here; the third box (one day of rocky's log) waits on #256.
Where a pre-tool moment's time goes (rocky,
916b0feb, read-only)Outside the server: TCP connect to
127.0.0.1:3773takes 0.3 ms p50, 0.4 ms max (172 probes). The old--connect-timeout 0.1was not what cut moments; the 1 s total was (contextmd#62). The HTTP span and the moment's own clock differ by p50 1 ms, max 9 ms (165 moments), so nothing sits between arrival andstartedAt.Inside the server, the work itself: every SQL step a pre-tool moment runs, timed alone against the live file (
mode=ro, 40 recent moments' threads, 2 runs each):resolveRun)Config, store and
headCommitreads are async file reads with no process spawn. Window building is therefore not the cost (refutes this Issue's inference).Inside the server, the wall time: pre-tool
server_ms, joined runs:over_budgetSince 20:03, Cue was mostly
not_called(live Cue on bestia is stopped overnight), yet pre-tool p50 is 625 ms. Cue's scoring is not the remaining cost either. Of the 42 cut pre-tool moments (33 above plus 9 cut before the join), 16 were cut before the run join and 24 after it. Cuts land at every stage, which fits waiting rather than one slow step.What the moment waits for: rocky's trace, 21:12 to 21:27Z (170 moments, 24
over_budget):chromeria-v2.sqlitespan over 100 ms (median overlap 409 ms and 196 ms). Only 32 of 91 moments under 600 ms did.provider_sessionsselect logged 747 spans over 100 ms in 15 minutes: that is queueing for the connection./healthanswers at p50 9 ms, p99 82 ms.Limits
/tmp/w248/on rocky (not committed).lukemaj commentedon Oct 14, 2026
Longer window, read-only, 2026-10-14, from the contextmd#13 close-out. Same direction as the 30-minute sample.
Rocky, 2026-10-13 15:35Z to 2026-10-14 07:08Z,
cue_msonok: user messages 94 ok and 46 timeout (33% of those two); tool results 2,458 ok and 297 timeout (11%). Timeouts do not store a window size. Among ok user messages, 1,500 to 2,999 tokens (n=15) median 566 ms, p90 640 ms, against the 650 ms wait. Among ok tool results, 3,000 or more tokens (n=140) median 906 ms, and all 140 are over 650 ms. Counts only.lukemaj commentedon Oct 14, 2026
2026-10-13 20:03:32 UTC to 2026-10-14 07:21:50 UTC, machine rocky
Example ids: 26749, 26792, 26796, 27015, 27045, 27058, 27149, 27190, 27741, 27903
Heartbeat age at the run: 28 s
ContextMD-Window: rocky cue/lost 1791921812-1791962510
fix(server): Cue waits up to 1.5 s for a score the moment needs now (#…
lukemaj commentedon Oct 14, 2026
Add to the paused Cue experiments (2026-10-14, Cue and capture thread): measure the Cue service's packed scoring at 64, 128, 256 and 512 entries per request (latency and GPU memory on bestia's 3090). Capture will add hundreds of Cue entries, and the service caps a request at 64 (
MAX_ENTRIESin contextmd/cue/service.py). The user prefers raising the cap over a retrieval pre-filter (contextmd#14 rejected that). It runs with the other paused overnight Cue experiments when the user resumes them.lukemaj commentedon Oct 14, 2026
What: Measured window replay, entry scaling and packing stability; neither tested shorter window nor a higher cap qualifies for a production change.
Why: Shortening changed fires; larger requests cost seconds and also changed scores/fires.
So what: Retain the current 10,000-character window, API cap 64 and physical cap 12,288 for now; continue measurement only. Live Cue stays stopped by the user's latest instruction.
Round 1 is written up. Prefix caching's 26 completed cases had zero reference fires and ended in a shape crash: preliminary speed evidence only. Students reached 124/207 ms p50/p90 but only 40.7% fire agreement; best observed agreement was 50.3%, below 95%. Policy replay reduced simulated Reflection events 46→36 while retaining 20 inherited yes-labelled first events; selected, unblinded labels and simplified delivery state support no production conclusion.
Replay: 197 reconstructed rocky moments, 40 user messages and 157 tool results, 24 reference fires.
Agreement = kept/(reference fires + extras). Both candidates miss the observed 95%/300-ms bars. Recommendation for #248: keep 10k, consistent with contextmd#20's accuracy choice; this does not prove every shorter policy fails. Fifteen selected moments were unjoined; only three threads had positive fires. Historical reconstruction is approximate: 11/33 live windows matched within five tokens. Reference agreement is not good-fire accuracy; production timeout/lost acceptance remains untested.
Entry scaling, 24 measurements/cell; instrumented service p50/p90 milliseconds:
This uses chunking at 12,288 tokens, repeating the window. Corpus: nine authentic entries plus 503 derived stress documents, not 512 authentic intents. A single physical 512-entry sequence took 14.51/17.73 seconds short/long; three repetitions of one moment are not population p90. Warmup produced one allocator OOM warning; sampled device peak 23,450 MiB left only 1,126 MiB.
Safe increase: not established; retain 64. Full-window 128 nearly doubles median latency versus 64, and every tested cap/order missed observed 95% preservation (84.0–93.4% at 128); some uncertainty bounds cross 95%. All 256/512 matrix round trips exceeded the current two-second transport limit.
The descriptive live-4B test baseline is P=.4535, R=.5021, AP=.4360, AUC=.9308 at .5625; validation-fitted .5 gives P=.4320/R=.5226. Entry-heldout only, historically exposed; never used for selection/promotion. The .393 figure was 0.6B.
Every experiment above received an independent Sol numeric check and separate Sol methodology review. Cue stopped 21:26:09Z and remains inactive/dead, PID 0; no restart, per superseding instruction. Stop/final state recorded and pushed in runbook 6e7a2c5. No production code/config changed.
lukemaj commentedon Oct 15, 2026
2026-10-14 07:21:50 UTC to 2026-10-15 04:00:01 UTC, machine rocky
Example ids: 28030, 28032, 28041, 28043, 28088, 28093, 28095, 28109, 28118, 28120
Heartbeat age at the run: 0 s
ContextMD-Window: rocky cue/timeout 1791962510-1792036801
lukemaj commentedon Oct 17, 2026
What: PR #391 candidate 0aa7a8b hit the existing ContextMD route deadline assertion in GitHub CI: 1,573 ms versus the 1,200 ms moment budget.
Why: The client-observed deadline was exceeded; the precise delay source is unproved, and these ContextMD source/test files are unchanged from the component base.
So what: The #379 planner records this on the existing latency owner and performs one bounded failed-job rerun before deciding whether a separate owning repair is required.
Job: https://github.com/toolboxmd/chromeria/actions/runs/39054473755/job/117459518766. Exact SHA
0aa7a8b246c904c35cebe4a06362ac99bbc2d0d9, basec28a6fa3763f13d7fd3272dfcf1157ec060faf2d. Failure:src/contextmd/ContextmdRoute.test.ts:1580, testreplies within the moment's budget when Cue never answers a failed call (#251). Server5 finished: 1 failed / 1,922 passed / 4 skipped, 332.76s. Other five server jobs passed, including the newly weighted authority workflow; Check fails correctly on this failure and skipped downstream transfer artifact.The test uses a never-answering Cue fixture and measures real client round-trip against MOMENT_BUDGET_MS. No threshold change, sleep/poll workaround or source edit was made. This is a real failed deadline observation, not a confirmed product regression or a confirmed infrastructure-only flake. Complete private job log retained at
/tmp/chromeria-391-0aa-server5.log. Current independent R8 reviews proceed against frozen source. One retry does not erase this evidence; recurrence requires diagnosis at this owner.lukemaj commentedon Oct 17, 2026
What: The single failed-job retry passed on unchanged candidate 0aa7a8b.
Why: Attempt 2 no longer exceeded the ContextMD route deadline; the original 1,573 ms failure remains a real observation with no proven delay source.
So what: No ContextMD code or assertion is changed in #379; retain the earlier evidence here for the latency owner.
Run https://github.com/toolboxmd/chromeria/actions/runs/39054473755, attempt 2, completed success on
0aa7a8b246c904c35cebe4a06362ac99bbc2d0d9, verified through the live run API. No further retry was issued. This does not close #248 or establish a product latency fix. #391 remains blocked by an independent authority finding in task cancellation, unrelated to this retry.lukemaj commentedon Oct 17, 2026
What: #248 now owns the Cue timeout health incidents previously tracked separately in #350.
Why: Both records describe the unresolved Cue timeout outcome; separate incident ownership split the machine evidence.
So what: Keep #248 open, preserve every transferred window below, and close #350 as duplicate.
Original incident: #350. Its unchanged body and all incident comments are retained below to preserve exact counters and health-report deduplication markers.
What: The serving health check found
cue/timeouton bestia over its threshold.Why: The daily check (toolboxmd/contextmd#40, #57) rates the serving log's stored statuses, outcomes and Cue results, and tool calls Agent Observer saw; this class is a defect this repository owns.
So what: An agent finds the cause and fixes it here; the check comments with each later window over the threshold.
ContextMD-Class: cue/timeout
2026-10-14 04:00:17 UTC to 2026-10-15 04:00:16 UTC, machine bestia
Example ids: 1054, 1326, 3281, 3348, 4398, 4419, 4463, 5068, 5105, 5196
Heartbeat age at the run: 9 s
ContextMD-Window: bestia cue/timeout 1791950418-1792036816
Elon record
Source observation: #350 (comment)
2026-10-15 04:00:01 UTC to 2026-10-16 04:00:05 UTC, machine cavallo
Example ids: 819, 824, 826, 831, 833, 835, 837, 839, 841, 848
Heartbeat age at the run: 20 s
ContextMD-Window: cavallo cue/timeout 1792036801-1792123205
Requirements and who asked: User approved the audited closure/consolidation batch on 2026-10-17.
Deleted: Duplicate or superseded tracking only; preserve source history, unique acceptance and active work.
Bottleneck: Tracker state had not been reconciled with delivered code or the accepted successor.
Checked myself: Original audit, current issue body/state, related issue and PR states immediately before this action, and exact after-state.
Reconciliation target: #248; action=consolidate-350-health-owner; force=false; branch-deletion=false; approval SHA-256=a414b3b77c8e190634da5ec3424c90beb56f9c8c8f2ce214978267d627690fe4.
lukemaj commentedon Oct 18, 2026
2026-10-16 04:00:05 UTC to 2026-10-18 04:00:04 UTC, machine cavallo
Example ids: 3646, 3661, 3750, 3770, 3782, 3805, 3807, 3809, 3998, 4017
Heartbeat age at the run: 9 s
ContextMD-Window: cavallo cue/timeout 1792123205-1792296005
lukemaj commentedon Oct 20, 2026
2026-10-19 04:00:00 UTC to 2026-10-20 04:00:24 UTC, machine bestia
Example ids: 246752, 246774, 246782, 246830, 246952, 246990, 247016, 247150, 247156, 247168
Heartbeat age at the run: 12 s
ContextMD-Window: bestia cue/timeout 1792382400-1792468825
lukemaj commentedon Oct 20, 2026
2026-10-19 04:00:05 UTC to 2026-10-20 04:00:05 UTC, machine cavallo
Example ids: 50216, 51636, 51638, 51642, 51644, 52300, 52345, 52572, 52574, 52985
Heartbeat age at the run: 26 s
ContextMD-Window: cavallo cue/timeout 1792382405-1792468806
lukemaj commentedon Oct 20, 2026
2026-10-19 04:00:01 UTC to 2026-10-20 04:00:15 UTC, machine rocky
Example ids: 61220, 61230, 61242, 61248, 61250, 61254, 61275, 61277, 61299, 61303
Heartbeat age at the run: -4 s
ContextMD-Window: rocky cue/timeout 1792382402-1792468815
lukemaj commentedon Oct 21, 2026
2026-10-20 04:00:24 UTC to 2026-10-21 04:00:24 UTC, machine bestia
Example ids: 306373, 306425, 306504, 306553, 306554, 306556, 306567, 306571, 306574, 306580
Heartbeat age at the run: 16 s
ContextMD-Window: bestia cue/timeout 1792468825-1792555225
lukemaj commentedon Oct 22, 2026
2026-10-21 04:00:24 UTC to 2026-10-22 04:00:08 UTC, machine bestia
Example ids: 346581, 346583, 346587, 346597, 346598, 346611, 346629, 346635, 346653, 346661
Heartbeat age at the run: 9 s
ContextMD-Window: bestia cue/timeout 1792555225-1792641609
lukemaj commentedon Oct 24, 2026
2026-10-23 04:00:24 UTC to 2026-10-24 04:00:14 UTC, machine bestia
Example ids: 351549, 351551, 351563, 351565, 351572, 351576, 351578, 351946, 351952, 351978
Heartbeat age at the run: 15 s
ContextMD-Window: bestia cue/timeout 1792728025-1792814415