Repository navigation
perf: long-session latency and sustained CPU — implementation tracker #1708
Description
Current status — 8 September 2026
This is the implementation tracker for severe long-session latency and sustained CPU. The earlier investigation below remains historical context. Its original ranking is superseded by the measurements and work list here.
Earlier evidence — 16:51–16:54 UTC
The owner's 16:51–16:54 UTC excerpt reports:
| Measurement | Observed value | Interpretation |
|---|---|---|
| Turn to upstream | 315.436 s | A large Lore-side delay before the model request |
| Semantic preparation | 0.464 s | About 0.15% of the measured interval; the earlier conversion/ID path does not explain this stall |
| Process CPU over that interval | 322.021 s | About one core on average, including background/native threads; not attributable to one request |
| Turn start to completed prewarm (derived) | ~296.505 s | Still needs stage attribution; not proof that prewarm itself took this long |
| Prewarm to gradient log | 18.894 s | The compression interval remains material |
| vec0 rolling p95 | ~34–38 s | End-to-end read time includes queue/IPC/event-loop delay as well as query execution |
The excerpt also includes local embedding initialization failure, temporal scheduler drain failure and sync fetch failures. These are correlated symptoms, not a proven single causal chain. Uncorrelated timeout lines must not be assigned to this turn merely because they are adjacent.
The bare drain-error format and absent source-window counters in this earlier excerpt suggested an older or mixed runtime. The later 20:00 excerpt below supersedes that concern for its observed diagnostic/checkpoint paths; exact artifact identity still needs verification.
Code inspection at a685d77 identifies independently actionable gaps: incomplete query cancellation, heavy synchronous fallback after read-worker failure, repeated visible-content BPE, exact-vector max-k scan amplification, and incomplete shared admission/deadline control. Profiling is still needed to attribute the full 315-second interval.
Latest evidence — 20:00 UTC
| Measurement | Observed value | What it establishes |
|---|---|---|
| Temporal drain | reason=deadline stage=embed elapsed_ms=61923 |
The 60 s whole-drain deadline fired before embedding completed; startup, queueing, inference and cleanup remain unsplit |
| Drain work | 8 messages, 31,092 input bytes, 9 units | Below the 256 KiB byte cap; units are not necessarily native batches and token/padding cost is unknown |
| Retry | failures=1 retry_ms=1000 |
First consecutive failure with the existing backoff; not evidence of a rapid retry loop |
| Separate checkpointed turn | 4 messages, 3 converted, checkpoint hit | The source-checkpoint path is in use |
| Semantic / turn-to-upstream | 12.619 ms / 1,630.327 ms | Semantic conversion is a small fraction of this turn; this is not a reproduction of the 7,228-message, 315 s stall |
| Loop delay / process CPU | 13.369 ms / 3,347.935 ms | No large loop stall measured for this turn; CPU includes concurrent/native work |
| Recall chain | 1 round, 24.477 s, no repeats or empty bodies | No loop in this chain; elapsed time includes upstream continuation, not just search |
The classified drain log and source-checkpoint counters show the #1724/#1726 paths are now active. They do not identify every live artifact or prove long-history performance is fixed. The temporal drain and recall logs lack enough correlation to assign them to the displayed four-message turn.
The ltm-budget → completed-prewarm gap is 1.556 s, including intervening LTM and prewarm work. Gradient logging follows about 1 ms later. Phase attribution remains necessary.
Source inspection at main aefb5612f60f confirms that these core embedding/scheduler files are unchanged from the earlier baseline. Local request abort already retires its assigned worker and awaits cleanup; the cooperative shutdown grace is 1.5 s before requesting forced termination. That could contribute to the drain's 1.923 s deadline overshoot, but is not measured here. A queued request timing out can also retire a shared worker. #1745 now owns that cancellation-isolation fix, split out of #1735.
The next focused diagnosis is #1734 with #1732's embedding phase timings. Keep model initialization failure and embedding-stage deadline as separate hypotheses until a reproduction connects them. #1745 is the first implementation task; #1735 then connects short foreground deadlines, and #1740 controls admission. The earlier vector tail and 315 s latency remain unexplained; this short turn does not resolve them.
Small implementation issues
Each linked issue has its own plan, scope boundary and acceptance criteria. “Independent” means no code prerequisite; it does not promise zero overlapping files.
| Order | Issue | Deliverable | Hard prerequisites |
|---|---|---|---|
| 1 | #1745 | Decouple request cancellation from embedding worker lifetime | Independent |
| 2 | #1735 | Bound/cancel LTM query embedding waits using that contract | #1745 |
| 3 | #1736 | Remove heavy synchronous failure fallback | Independent |
| 4 | #1737 | Reuse exact visible-content token counts | Independent |
| 5 | #1738 | Remove avoidable max-k vector scan amplification | Independent |
| 6 | #1739 | Bound read-pool admission and prioritize foreground work | Independent |
| 7 | #1740 | Gate maintenance batches on foreground/runtime pressure | Independent |
| 8 | #1741 | Integrate a shared preparation deadline with safe fallback | #1735, #1736, #1739; worker lifetime transitively through #1735 |
| Alongside | #1731 | Verify gateway/core/worker build identity | Independent |
| Alongside | #1732 | Attribute preparation, embedding phases and worker service | Independent |
| Alongside | #1733 | Reproducible long-session/mixed-load baseline | Independent |
| Alongside | #1734 | Reproduce the local-init failure / embedding-stage deadline and repair its demonstrated cause | Affected-environment evidence; no code prerequisite |
| Conditional | #1742 | Decide whether an ANN side index is actually needed | #1738 and #1733; only if exact service time misses its budget |
The owner selected independent embedding worker lifetime as the highest-priority implementation work. Start #1745: queued cancellation removes only that job, executing work retains its actual capacity ownership after caller cancellation, and worker-owned failure/watchdog policy governs restart. Runtime shutdown and explicit configuration replacement remain valid lifecycle operations.
#1735 is now a smaller follow-up that connects LTM signals, short deadlines and FTS fallback; it depends on #1745. #1731, #1732, #1733 and #1734 can proceed alongside this fix. A dedicated child process or broader embedding service rewrite is not a prerequisite.
#1737 and #1738 remain independent. Coordinate changes to vector-pool/read helpers between #1736, #1739 and #1732, and reuse #1745's minimal worker-control acknowledgements in #1732 rather than creating a second protocol.
Related standalone issue: #1747 covers recall continuations after the initial model request. It is outside this implementation plan and is not a dependency or completion requirement for #1708.
Existing work to reuse
- Quick win: eliminate full-history temporal-ID N+1 work before upstream #1712/fix(perf): batch temporal ID lookups and eliminate duplicate history preparation #1714: batched historical IDs and removal of duplicate preparation — merged.
- fix(perf): reuse exact provenance token counts across restarts #1717: durable exact provenance-token counts — merged.
- Make long-session resume O(delta): persist a source transcript frontier and active model window #1710/fix(perf): resume semantic preparation from durable source windows #1726: source frontier and bounded active window — merged; do not reopen/reimplement it as the main explanation for this trace.
- fix(core): diagnose temporal embedding drain failures and back off retries #1723/fix(core): diagnose temporal embedding failures and back off retries #1724: temporal drain diagnostics/backoff — merged; actual provider-failure / embedding-stall diagnosis and repair remain fix(embeddings): diagnose and repair provider failures and stalls #1734.
- perf(core): move vec0 orphan discovery off startup and the event loop #1681/fix(core): move startup vector orphan discovery to idle read workers #1727: idle/off-thread startup orphan discovery — merged.
- Stream and selectively parse large compressed LLM request bodies #1711 / PR feat(gateway): stream large Responses request bodies #1728: complementary ingress streaming; its memory benefits do not establish a fix for post-decode CPU/latency.
- hardening(gateway): define global resource budgets and graceful drain deadlines #1617: broader global resource-budget inventory; fix(reads): keep heavy worker failures off the gateway thread #1736, perf(workers): bound read-pool queues and prioritize foreground requests #1739, perf(background): gate maintenance batches on foreground and runtime pressure #1740 and fix(gateway): enforce a shared memory-preparation deadline with safe fallback #1741 are focused implementation slices.
- Introduce scoped runtime lifecycle and drainable background services #1672: scoped lifecycle and drain contracts; fix(embeddings): decouple request cancellation from worker lifetime #1745 supplies the embedding request/worker ownership contract, and perf(background): gate maintenance batches on foreground and runtime pressure #1740 composes with the existing hooks. Neither requires a process-wide rewrite.
- perf(gateway): reduce per-turn SQLite span amplification #1685: reuse the mixed-load harness to quantify SQLite-span overhead; no duplicate instrumentation-volume issue.
- perf(core): batch temporal and telemetry writes behind bounded queues #1619: eligible SQLite write batching remains separate from safe read-worker failure handling.
- perf(opencode): attribute recurrent V8 OOM and progressive server starvation #1683/Incident: temporal embedding backlog starves OpenCode and ends in V8 OOM #1686: retain the existing heap/earlier incident investigations; the new excerpt does not establish OOM or the retained heap owner.
Completion criteria
- Verify the deployed source/bundle/worker identities and reproduce in a fresh serving process.
- Attribute preparation and vector service versus waiting; make the remaining unexplained time explicit.
- On a documented reference machine/workload, target p95 post-decode Lore overhead <2 s and health p95 <250 ms, including supported degraded-provider cases. Exclude wire upload and upstream model inference, and report hardware/sample count.
- Queues and retained bytes remain bounded, background work eventually progresses, and abandoned work cannot keep consuming unaccounted capacity.
- Ordinary request cancellation leaves healthy embedding workers alive. A retry cannot duplicate the same still-running durable job; native work remains owned until completion or confirmed worker exit.
- Preserve source/window correctness, current-turn tools and provenance, tenant/project visibility, prompt/token limits, and transactional temporal/checkpoint writes.
- Judge approximate retrieval by a declared quality bar before adoption. Never silently discard older memory to meet a latency target.
Historical investigation
The original report and hypotheses follow unchanged for provenance. Statements about missing source-frontier support and the primary semantic bottleneck describe the earlier implementation, before the merged fixes above.
Expand the original report and hypotheses
Symptom
On very long OpenCode sessions, Lore progressively becomes sluggish and may hold CPU near 100% between turns. The first request after restarting Lore is also extremely slow despite no OOM or obvious heap leak.
Concrete reproduction evidence
A real resumed Tier-1 OpenCode session produced:
13:37:39.461 turn: session=… messages=5580 model=gpt-5.6-terra new=false tier=1
13:37:39.829 models.dev loaded
13:37:39.831 max_tokens resolved
13:38:53.865 ltm-budget
13:38:54.261 distillation prewarm: 38 rows
13:38:55.690 gradient: layer=3 tokens=180409 (distilled=17306 raw=163103)
13:38:55.710 first conversation upstream request
Key implications:
- Lore had already received and parsed the request at the
turn:log. - It then spent roughly 74 seconds before
ltm-budget. - Gradient/prewarm/compression from
ltm-budgetto upstream took only about 1.8 seconds. - The pathological dimension is likely structural history (
5,580messages and many tool/provenance parts), not only token count (~180k). - “OpenCode reconstructs the session” may contribute before request arrival, but it does not explain the measured Lore-side stall.
Updated leading diagnosis
Lore rebuilds the entire semantic transcript on every turn, including a known resumed session:
full req.messages
→ gatewayMessagesToLore(all messages)
→ complete-content current + legacy hashes
→ per-part hashes and object allocation
→ provenance token estimation
→ provenance map over full history
→ three-pass tool-result resolution
→ synchronous storedMessageId compatibility lookups
→ gradient/LTM
For tool-heavy coding sessions, resolveToolResults can call temporal.storedMessageId() once for many historical tool-result-only messages. That function performs a synchronous SQLite lookup to support pre-v82 identities, creating a plausible main-thread N+1 query path.
Post-response bookkeeping can also rebuild/resolve the complete source transcript although it ultimately persists only the latest user message and new assistant response.
The architectural problem is that Lore persists substantial session state but not a durable source transcript frontier or active semantic/model-window checkpoint. After restart it knows counts, LTM pins, route state, recall state and gradient calibration, yet still reprocesses all 5,580 source messages.
Experiment result: embedding-pool oversubscription demoted
LORE_EMBED_POOL_SIZE=1 did not improve the problem and may have made it slower. This strongly demotes the previous “two native ORT workers oversubscribe the host” theory as the primary cause. The second worker appears more likely to help drain real embedding work.
Embeddings may still contribute to sustained idle CPU, especially when a long temporal queue is draining, but they do not explain the measured 74-second pre-LTM cold-resume interval.
Background-worker degradation is an amplifying failure
The same session repeatedly surfaces:
Lore: Background workers (distillation, curation, cache warming)
for this session have been failing for 42m+ …
At least one distillation later succeeded, so the worker subsystem is not completely dead, but query expansion timed out and sustained worker-health failure was recorded.
Likely feedback loop:
worker calls fail or time out
→ distillation falls behind
→ raw structural history remains large
→ every turn rebuilds/re-resolves more messages
→ foreground latency and idle workload worsen
The worker failure reason/model still needs to be identified from Sentry/dashboard (no-response, parse/protocol/auth/rate-limit/etc.). Fixing worker reliability is necessary, but it should not be required for the foreground request path to scale safely.
Child implementation issues
- Make long-session resume O(delta): persist a source transcript frontier and active model window #1710 — Make long-session resume O(delta): persist a source transcript frontier and active model window.
- Stream and selectively parse large compressed LLM request bodies #1711 — Stream and selectively parse large compressed LLM request bodies.
#1710 is the primary fix. #1711 is complementary: JSON decode occurs before the measured 74-second interval, but streaming parsing can reduce peak copies and—combined with the frontier—validate/discard historical input without materialising it.
Immediate instrumentation required
Add stage spans/counters around the section between turn: and ltm-budget:
gatewayMessagesToLoreduration;- source message/part/provenance byte counts;
- provenance-map duration;
resolveToolResultsduration;- count and total time of
storedMessageIdlookups; - request decode /
JSON.parse/ protocol-normalisation durations; - post-response conversion/storage duration;
- process CPU delta and event-loop lag;
- temporal embedding queue depth and drain state;
- resolved worker provider/model/worker kind and failure reason.
Expected diagnostic shape:
request.decode
request.json_parse
request.protocol_normalize
semantic.gateway_to_lore
semantic.provenance_map
semantic.resolve_tools
semantic.storage_id_queries
ltm.select
gradient.transform
upstream.start
Current hypothesis ranking
- Full-history semantic reconstruction and synchronous identity resolution — primary explanation for cold/resume latency and likely per-turn scaling.
- Failed/slow background workers leaving excessive raw history — major amplifier.
- Temporal embedding backlog consuming CPU between turns — plausible contributor to sustained idle CPU.
- OpenCode's own reconstruction before Lore receives the request — separate upstream/client cost.
- Embedding-pool worker multiplication / ORT oversubscription — now low probability as the primary issue.
Success criteria
- A valid resumed turn performs semantic work proportional to the new suffix plus a bounded active window, not all source history.
- The 5,580-message fixture improves by at least an order of magnitude from the observed pre-upstream baseline.
- No historical-message-count-proportional SQLite query set occurs on the foreground path.
- Worker failure cannot make foreground processing grow without bound.
- Streaming/body work is separately measured so client reconstruction, ingress decode and Lore semantic preparation are distinguishable in Sentry.
- Correctness survives restart, tool calls crossing the frontier, recall markers, encrypted/opaque Responses provenance, compaction, branch/rewind and crash replay.
Activity
BYK commentedon Sep 6, 2026
Deeper static-analysis findings
The initial ranking shifts: the local embedding subsystem is now the strongest suspect, more than generic idle-scheduler overlap.
1. Temporal embedding scheduler is serialized, but continuously polls
packages/core/src/temporal-embedding-queue.tshas a process-wide scheduler with anactiveDrainguard, so concurrent drains collapse onto one promise. That makes a classic overlapping-drain storm less likely.However:
processed > 0) → next drain in 0 msSo this subsystem is permanently active during user-idle time, and will aggressively drain any backlog.
2. Embedding pool grows lazily and does not shrink in normal operation
EmbeddingPoolgrows when the best healthy worker is busy, up to a memory-gated ceiling (default max pool = 2, configurable hard max = 8). Normal healthy workers are retained; they are only retired on failure/shutdown.Each slot owns a
LocalProvider, which owns its own ONNX Runtime model/session/thread pool.This fits the 'gets worse after several turns' shape if later turns introduce enough concurrent recall/backfill work to grow the pool and keep multiple native ORT sessions resident/active.
3. Native ORT thread pools are mostly left at their defaults on ordinary hosts
Lore only passes
session_options.intraOpNumThreadswhenavailableParallelism() < os.cpus().length(i.e. a CPU-constrained container). On an unconstrained workstation it deliberately leaves ORT's default thread count untouched.ONNX Runtime's documented defaults are important here:
session.intra_op.allow_spinning = 1)Lore currently does not appear to set the ORT spinning controls in the embedding worker's
session_options.With 2 persistent local embedding workers, this potentially means two host-core-sized native ORT pools. This does not yet prove the sustained 100% CPU symptom (spinning may settle), but it is a much stronger concrete CPU mechanism than the generic scheduler theory.
4. Existing Sentry resource gauge does not currently measure CPU
emitResourceGauge()captures memory (rss, heap/external/arrayBuffers) and event-loop-delay p99, but I found no process CPU metric. So current Sentry data may confirm event-loop impact but cannot directly tell us whether the gateway/native workers are burning CPU.Fast discriminating experiments
Before a large profiling change, run the same reproduction with these A/Bs:
embedPoolSize = 1Instrumentation I would add next
process.cpuUsage) emitted on the existing 30s resource gaugeactiveDrainboolean + drain duration + messages/chunks processedThose metrics should let one Sentry timeline distinguish queue backlog from persistent native worker CPU without immediately reaching for an external profiler.
[-]Investigate runaway CPU after several turns / idle background work saturation[/-][+]Investigate runaway CPU: temporal embedding drain × native ORT worker oversubscription[/+][-]Investigate runaway CPU: temporal embedding drain × native ORT worker oversubscription[/-][+]Very long sessions: 74s pre-upstream resume latency and sustained CPU[/+]BYK commentedon Sep 7, 2026
Added the narrow first implementation task: #1712 — eliminate the full-history temporal-ID N+1 work and duplicate post-response reconstruction, with stage timings and a 5,580-message benchmark. This should be attempted before the larger #1710 checkpoint redesign or #1711 streaming parser.
BYK commentedon Sep 8, 2026
Production follow-up supplied by the user after activating the merged #1717/#1719 version, 7 September 2026 (UTC):
temporal embedding scheduler drain failedat23:55:31.663 and23:56:35.459, plus local@huggingface/transformersinitialization failure at23:56:32.364. Recall explicitly falls back to FTS-only. Startup reports10,495 distillations pending embedding. There is no successful embedding completion in this excerpt, and the underlying initialization cause is not shown.#1710 remains relevant for bounded cold/source processing; #1718 is the next focused fix for accurate LLM-worker recovery warnings. LLM-worker health and local embedding initialization are separate subsystems.
[-]Very long sessions: 74s pre-upstream resume latency and sustained CPU[/-][+]perf: long-session latency and sustained CPU — implementation tracker[/+]fix(embeddings): decouple cancellation from worker lifetime (#1751)
fix(reads): keep heavy worker failures off the gateway thread (#1890)
fix(gateway): enforce a shared memory-preparation deadline (#1892)