← plans · tool-latency-instrumentation · DESIGN23 Jul 2026

Chat pre-turn parallelization + real tool duration_ms — design spec

Status: Approved
Author: Claude (NOS-212 orchestrator)
Date: 2026-07-23
Repo: north-os (packages/chat-runtime, packages/agent-runtime)
Related: Linear NOS-212; retrieval-speed batch 2026-07-23 (Fix 4 — the measurement backbone); analytics taxonomy (agent.tool_invoked)

Problem (measured)

  1. Serial pre-turn dead time. packages/chat-runtime/src/run.ts runs three independent loads as serial awaits before graph.stream on every turn: memory load (measured 257ms), thread-ledger load, and context-digest load — each in its own transaction. Total ~600ms of pre-LLM dead time where ~300ms (the max of the legs) would do.
  2. Instrumentation blackout. Every chat tool's agent.tool_invoked product_event carries duration_ms: 0 (verified in the dev DB). recordToolAudit records outcome only; the ~50 tool call sites never time themselves. Only knowledge search measures its own latency (knowledge_retrieval_latency_ms). When a turn is slow we cannot tell which tool ate the time, and the retrieval-speed batch (NOS-209/210/211) has no queryable proof or regression tripwire.

Design

1. Pre-turn Promise.all (chat-runtime)

Wrap each of the three loads in an async closure that keeps its existing non-fatal try/catch, then run:

await Promise.all([loadMemoryBlock(), loadLedgerThenDigests()])

Expected effect: pre-turn wall clock drops from memory + ledger + digest to max(memory, ledger + digest). Measured on a real HSE thread (dev DB): memory 264ms, ledger 5ms, digest 2ms — so the saving is the ledger+digest tail (~10–20ms p50 on light threads, more on ledger-heavy ones), NOT the batch table's ~300ms headline (that figure spans the whole pre-LLM path). The memory leg dominates and is explicitly out of scope (marked "fine" in the batch baseline).

Accepted tradeoffs (from plan review): (a) digest freshness — a digest committed by the async context worker during the memory-load window could be seen by the serial code but missed by the parallel code; raw checkpoint fidelity wins in that case, which is the documented fail-open behavior, so this is a freshness tradeoff, not a safety change. (b) pool pressure — the parallel legs hold up to two pool connections per turn while memory ranking may wait on the embedding provider; the proof gate therefore includes a 10-concurrent pre-turn probe, not just sequential medians.

2. Real duration_ms at the audit seam (agent-runtime)

The codebase already documents the constraint (tool-audit.ts doc comment): timing belongs at the toolNode choke point, but the agent.tool_invoked emit cannot move there without losing the closed-enum outcome computed inside each tool. We bridge the two with an AsyncLocalStorage deferred-emit design — no changes to the ~50 tool call sites, and the measured span is the FULL invocation (plan review found that measuring at audit time misses e.g. search_knowledge's filtered-miss second search, which runs after its success audit — exactly the slow path we must see):

Accepted edges: a tool that audits and then interrupts without ever resuming emits no event (today it would emit one with duration_ms: 0); tools that never call recordToolAudit (e.g. echo) get histogram samples but still no product_event — unchanged, out of scope.

3. Proof harness (the batch's regression tripwire)

p50/p95 per tool becomes queryable from the product-analytics stream:

SELECT props_redacted->>'tool_name'                            AS tool_name,
       count(*)                                                AS calls,
       percentile_cont(0.5)  WITHIN GROUP
         (ORDER BY (props_redacted->>'duration_ms')::numeric)  AS p50_ms,
       percentile_cont(0.95) WITHIN GROUP
         (ORDER BY (props_redacted->>'duration_ms')::numeric)  AS p95_ms
FROM product_event
WHERE event_name = 'agent.tool_invoked'
  AND created_at >= '<deploy timestamp>'
GROUP BY 1 ORDER BY p95_ms DESC;

Before this change every row reads 0; after, real wall-clock durations. The created_at filter is load-bearing: historical rows all carry 0, so an unfiltered p50 stays 0 forever. When validating, report count(*) FILTER (WHERE (props_redacted->>'duration_ms')::numeric = 0) alongside rather than silently excluding zeroes.

Alternatives rejected

Gates