From e7ce9899f31a5198d19772b564ece97b8d4d2306 Mon Sep 17 00:00:00 2001 From: dtzp555-max Date: Mon, 13 Jul 2026 16:30:55 +1000 Subject: [PATCH] =?UTF-8?q?docs(plans):=20TUI=20streaming=20IS=20achievabl?= =?UTF-8?q?e=20(MessageDisplay=20hook)=20=E2=80=94=20prereq=20spike=20+=20?= =?UTF-8?q?honest=20latency=20constraints=20(#157)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * docs(plans): TUI streaming is not achievable — prereq spike result + honest README constraints Backlog #2 of docs/plans/2026-07-13-tui-latency demanded a prereq spike before any streaming design: does the transcript JSONL grow during a turn, or only at the end? The spike was run. All three candidate sources are dead: (a) transcript JSONL — grows at EVENT granularity; the assistant's text event is written as ONE complete line, ~0.3s before the terminal turn_duration event (observed: turn_duration 7319ms; text event at t+7.0s, terminal at t+7.3s). (b) tmux capture-pane — the pane is a RENDERED view, not the text. Same turn, transcript T = '## Semaphore\n\nA **semaphore** is a synchronization…' pane = '⏺ Semaphore' / ' A semaphore is a synchronization…' '## ', '**' and ```-fences are absent from the pane entirely (rendered to ANSI, then stripped by capture-pane -p). T.startsWith(paneText) is FALSE both raw and indent-stripped — not on redraw, but on essentially every markdown answer. capture-pane -e recovers styling, never source spelling: no unique inverse. (c) --debug-file — byte-exact ('last_assistant_message':'## Title\n\n**alpha…'), but only inside end-of-turn Stop-hook payloads; zero content_block_delta / text_delta events; ~2.7MB per turn. --output-format stream-json, the only interface emitting token deltas, requires -p — the metered-billing path TUI mode exists to avoid (cc_entrypoint=sdk-cli). The constraint is structural. OCP's TUI SSE is, and remains, replay-only. Also corrects this plan's own "~20s waiting for the whole turn" decomposition, which was inferred from an external 30-32s report and never measured through OCP. Measured through a real OCP instance (TUI, claude-sonnet-4-6, n=5): median 11.30s before #156, 9.55s after, vs a native turn_duration of ~7.3s → OCP's own overhead is ~2-4s, not ~20s. The remainder is generation time, which streaming would not shorten (it moves the first byte, not the last) — so a consumer needing the COMPLETE answer, which is the JSON-card case that motivated this work, would have gained nothing from streaming. Backlog #4 measured while here: --exclude-dynamic-system-prompt-sections gives ZERO marginal benefit (TTFT median 6.39s vs 6.17s for --effort low alone, n=5, one worse outlier). Do not adopt. Banner stayed on Claude Max. README: documents the ~6s TTFT floor plainly (TUI mode cannot serve interactive-latency consumers) and states that no-token-streaming is structural rather than a missing feature. No code change. No version bump (docs-only). Not endpoint-touching: no server.mjs diff, so no cli.js citation applies. Co-Authored-By: Claude Fable 5 Claude-Session: https://claude.ai/code/session_01VqgWJcjxrjjL9L9SkpZyXR * docs: fold in adversarial review — correct the debug-log reasoning + the overhead number Independent adversarial reviewer (tasked with REFUTING this doc) confirmed the central claim — no byte-faithful incremental source exists on the TUI path — but found four factual defects in the prose. A negative claim that will be cited for years has to be right in its reasoning, not just its conclusion. 1. --debug-file: the "written at end-of-turn" reasoning was WRONG. The default log level is `debug`, which suppresses every `verbose` site; the original probe therefore ran with the stream logging OFF. At CLAUDE_CODE_DEBUG_LOG_LEVEL=verbose there ARE 16 mid-turn `[shoji-engine] yield stream_event/-` lines spread over ~3.9s of generation. The conclusion survives because those lines carry TIMING ONLY, no text payload (content_block_delta / text_delta / content_block_start / message_start = 0 at any verbosity or category filter). Reasoning rewritten: "logs when tokens arrive, never what they are" — as written before, the doc was falsifiable in 30 seconds. 2. The 7.319s `turn_duration` is NOT a "native" (non-OCP) baseline: it comes from an OCP-driven turn (cwd .ocp-tui/work, same 7451-char prompt, same 204-char answer as pr1 baseline row i=5, elapsed 11563ms). Reframed as what it actually is — a SAME-TURN decomposition, 11.563s wall - 7.319s CLI-internal = ~4.2s OCP overhead (n=1), which is a cleaner comparison than the doc originally claimed. 3. Dropped the "~2-4s" range: its low end mixed an effort-HIGH turn_duration with the effort-LOW wall-clock median, which understates overhead (a low-effort turn generates faster, so its own turn_duration would be lower). No turn_duration sample exists for the effort-low config. Now stated as ~4s (n=1, baseline config), with both caveats. 4. Softened "ZERO marginal benefit" (backlog #4) to "no benefit detectable at n=5" — n=5 cannot prove zero — and added the mechanistic reason the reviewer supplied, which is far stronger than the empirical null: `--help` says the flag improves cross-user prompt-cache REUSE, and OCP is single-user, so there is no cross-user cache to share. Also folded in the reviewer's independent sweep, which closes the search space rather than sampling it: the hook registry was enumerated from the shipped binary (no per-chunk / streaming hook exists among the 21 events); `capture-pane -e` was tested and shown to be a provably non-unique inverse (an H2 and a bold span emit IDENTICAL SGR 1); and sessions/.json, history.jsonl, CLAUDE_CODE_INCLUDE_PARTIAL_MESSAGES (undocumented), sessionMirror, --sdk-url and --input-format stream-json were each checked and each dies (contentless, or gated behind --output-format stream-json -> --print -> the metered sdk-cli pool). Prompt-mutation (asking the model for plain text) is named and rejected on ALIGNMENT grounds so it is not re-litigated later. Docs-only. No code change, no version bump. Co-Authored-By: Claude Fable 5 Claude-Session: https://claude.ai/code/session_01VqgWJcjxrjjL9L9SkpZyXR * docs: REVERSE the streaming verdict — MessageDisplay hook makes it achievable The previous commit on this branch concluded TUI streaming was impossible. That was WRONG, and this corrects it before it could be merged. The adversarial reviewer commissioned to refute the claim found, on a second pass while verifying the fold-in, that its OWN first-pass hook enumeration had been truncated by a 400-char grep cap: it reported 21 hook events; the shipped 2.1.207 bundle has 30. Event #30 is MessageDisplay. Independently reproduced before acting on it (30 events confirmed via `strings` on the binary; payload shape `hook_event_name:"MessageDisplay",turn_id,message_id,index,final, delta`), then live-tested with a MessageDisplay command hook registered via --settings on a PLAIN INTERACTIVE TUI spawn (no -p, no --bare), claude-sonnet-4-6, --effort low: banner: "Sonnet 4.6 with low effort · Claude Max" ← subscription pool, verified 7 fires, mid-turn, spread across generation: index=0 final=false '## Mutex\n\n' index=1 final=false 'A **mutual exclusion lock** prevents concurrent access to a shar…' index=4 final=false 'let counter = 0;\n\nasync function increment() {\n const release =…' index=6 final=true '```' concat(deltas) === T (transcript-authoritative) -> TRUE (579 == 579 bytes) T.startsWith(S) at EVERY step -> TRUE (prefix-stable) '## ' / '**' / '```javascript' present in deltas -> raw markdown SOURCE, not rendered This satisfies every invariant the previous version declared unobtainable: byte-faithful, incremental, prefix-stable, no -p, subscription pool. Granularity is block-level (~5-7 chunks/answer), not token-level — which is all an SSE delta.content needs. Backlog #2 REOPENS and should be built. Implementer caveat recorded: the hook's source sets forceSyncExecution -> claude BLOCKS on it, so the hook must write and exit immediately (FIFO/socket), never work inline. Only text blocks fire it (thinking excluded). ALIGNMENT: consumes claude's OWN hook surface as emitted — forwarding, not inventing (Class B / ADR 0007; no cli.js citation applies). Everything still true is kept, and the dead ends are kept as dead ends (they document what NOT to build): the pane is a rendered view whose source markers are irrecoverable (capture-pane -e emits IDENTICAL SGR 1 for an H2 and a bold span — a provably non-unique inverse); the transcript is event-granular; --debug-file carries timing but no payload; --output-format stream-json requires -p (the metered pool). Also kept: the ~4s (n=1 same-turn) overhead correction, backlog #4's null result with its mechanistic single-user reason, and the honest value framing — streaming moves the FIRST byte, not the last, so the complete-answer consumer that motivated this work gains nothing from it. The wrong conclusion and its refutation are both preserved in the doc. "We checked, it's impossible" is the most expensive claim to get wrong: it closes a door nobody re-opens. Docs-only. No code change, no version bump. Co-Authored-By: Claude Fable 5 Claude-Session: https://claude.ai/code/session_01VqgWJcjxrjjL9L9SkpZyXR * docs: fold in re-review — the two caveats that would have bitten the implementer Re-review of the reversed doc came back APPROVE_WITH_MINOR. The reversal itself was verified complete (worktree-wide grep: no surviving impossibility claim) and NOT over-claimed in the other direction (the reviewer recomputed every headline number from the committed messagedisplay-deltas.jsonl and re-ran the invariant on two further turns: 4 independent turns total, 5/6/4/18 fires, 609/696/239/1973 bytes, concat(deltas) === T TRUE in all four). But two additive caveats were missing, and both are load-bearing for the streaming PR now in flight: 1. CONCURRENCY DEMUX (severe, and live TODAY — not a warm-pool future problem). OCP_TUI_MAX_CONCURRENT defaults to 2, so two `claude` processes already run concurrently. One MessageDisplay hook writing to one shared sink would INTERLEAVE deltas from two different turns into a single stream — request A's client receiving request B's text. A single-request test never surfaces it. The payload carries session_id, so the sink must be keyed by it (which also keeps the design warm-pool compatible: a pre-booted pane's session-id is fixed at boot, so one static hook script serves every pane). Documented, with the required ≥2-concurrent-request test. 2. THINKING-EXCLUSION IS NOT STRESS-TESTED (severe if wrong). The exclusion was inferred from a code snippet that turns out to be the final:true call site, not the incremental one. Four live turns showed no thinking in any delta — but every transcript's thinking block was EMPTY (thinking:"", 0 chars), so it was never actually stressed. If thinking deltas do fire on Opus/xhigh, concat(deltas) !== T AND OCP streams the model's private reasoning to the caller; the concat === T assertion detects that but cannot un-send an SSE delta. Flagged as a must-verify-before-shipping item. Also: the "5-7 chunks per answer" figure is size-dependent (18 fires on a ~2 KB answer) — rescoped to "once per rendered block, scales with answer length" in both the doc and the README, so no implementer hard-codes a chunk-count assumption. Both caveats were relayed to the streaming implementation immediately rather than waiting for this merge. Docs-only. No code change, no version bump. Co-Authored-By: Claude Fable 5 Claude-Session: https://claude.ai/code/session_01VqgWJcjxrjjL9L9SkpZyXR --------- Co-authored-by: dtzp555 Co-authored-by: Claude Fable 5 --- README.md | 31 ++- docs/plans/2026-07-13-tui-latency/README.md | 52 +++- .../messagedisplay-deltas.jsonl | 7 + .../prefill-spike-measurements.jsonl | 5 + .../2026-07-13-tui-latency/streaming-spike.md | 256 ++++++++++++++++++ 5 files changed, 347 insertions(+), 4 deletions(-) create mode 100644 docs/plans/2026-07-13-tui-latency/messagedisplay-deltas.jsonl create mode 100644 docs/plans/2026-07-13-tui-latency/prefill-spike-measurements.jsonl create mode 100644 docs/plans/2026-07-13-tui-latency/streaming-spike.md diff --git a/README.md b/README.md index 68f506f..d182d78 100644 --- a/README.md +++ b/README.md @@ -1033,7 +1033,7 @@ Then restart OCP. At boot you will see (with the env token set, isolated home au ### What changes / what doesn't - **Callers see no API change.** The response is a normal OpenAI completion object or chunked SSE — identical wire format. -- **No real token streaming.** TUI-mode buffers the full response then replays it as chunked SSE. You will see a delay then the complete response rather than real-time tokens. +- **No real token streaming *today* — but it is achievable, and planned.** TUI-mode currently buffers the full response then replays it as chunked SSE: you see a delay, then the complete response. This is a limitation of the current implementation, **not** of the path — `claude` fires a `MessageDisplay` hook carrying incremental, byte-faithful `delta`s of the raw reply (they concatenate exactly to the final text, and stay prefix-stable), on the subscription pool, without `-p`. Wiring it into OCP's SSE is tracked as backlog item #2. What is *not* available is token-by-token granularity (the hook fires once per rendered block — roughly one per paragraph, list item, or code block, so the count scales with answer length) — which is plenty for SSE. Evidence: [`docs/plans/2026-07-13-tui-latency/streaming-spike.md`](docs/plans/2026-07-13-tui-latency/streaming-spike.md). - **Cache and singleflight work normally.** TUI-mode writes the buffered response to the cache on success; cache-hits skip the interactive turn entirely. - **The host's `CLAUDE.md` / auto-memory is never injected.** OCP is a proxy — the proxied client (OpenClaw / your IDE) owns its own context and memory. TUI-mode always runs `claude` with `CLAUDE_CODE_DISABLE_CLAUDE_MDS` + `CLAUDE_CODE_DISABLE_AUTO_MEMORY`, so a `CLAUDE.md` on the OCP host can never leak into proxied turns (verified live; see #4). Built-in tool schemas + the interactive system prompt remain (the inherent ~20–35K context floor of interactive mode); MCP is hard-disabled. - **Authenticate via `CLAUDE_CODE_OAUTH_TOKEN` in a credential-isolated home (recommended).** tmux does not forward the parent process's env to the pane, so OCP sets the token explicitly on the spawned `claude` when `CLAUDE_CODE_OAUTH_TOKEN` is present. But passing the token is **not enough on its own**: interactive `claude` *prefers* `~/.claude/.credentials.json` over the env var (unlike the `-p` path), so a stale `credentials.json` would shadow the token. With the env token set and `OCP_TUI_HOME` unset, OCP therefore runs claude in a **credential-isolated home** (`$HOME/.ocp-tui/home`) that has **no `credentials.json`** — so the env token is the only credential and is authoritative, and claude never runs the token-refresh path (so the single-use refresh token can't be corrupted by the spawn/teardown cycle). On a long-running host the credentials.json path produced a permanent `Please run /login · API Error: 401` that re-login could not fix (the next spawn re-corrupted it); the isolated home ends that at the root. Transcripts land under the same isolated home, so the answer-reader is unaffected. Without the env token, claude falls back to the real home's `credentials.json` (byte-for-byte the previous behaviour). (The token is visible in `ps` on the pane command — acceptable for the single-user A-path; the multi-user B-path is refused at boot.) See ADR 0007 PR-C / PR-D amendments. @@ -1041,6 +1041,35 @@ Then restart OCP. At boot you will see (with the env token set, isolated home au - **Default path unchanged.** Unset `CLAUDE_TUI_MODE` and restart → `callClaude` / `callClaudeStreaming` are used again, byte-for-byte identical to today. - **Concurrency is bounded separately.** TUI turns are heavy (per-request cold-boot + long wallclock), so the TUI path has its own limiter — `OCP_TUI_MAX_CONCURRENT` (default `2`), independent of `CLAUDE_MAX_CONCURRENT`. Excess turns queue; a full queue returns a 503. Tune it up only on a host that can run more interactive `claude` sessions at once. +### ⚠️ Latency: TUI mode has a ~6-second floor, and it is immovable + +**TUI mode cannot serve real-time or interactive-latency consumers.** This is a hard property of the +path, stated plainly so you can rule it out before building on it: + +| | measured | +|---|---| +| **TTFT floor (first token)** | **≈ 6 s** — immovable | +| cold boot → input bar ready | ~1 s (per request; not the bottleneck) | +| OCP's own overhead above the CLI | ~4 s (n=1 same-turn decomposition) | +| direct Anthropic API, same prompt (for scale) | 0.84–1.64 s | + +The ~6 s floor is the `claude` CLI itself: it always injects the full Claude Code system prompt plus +its tool definitions before your prompt, on every turn, no matter what you ask. No flag removes it +(`--exclude-dynamic-system-prompt-sections` was measured: **no effect** on the floor). Extended +thinking is *not* the cause — `OCP_TUI_EFFORT` already defaults to `low`, which is what cuts a +formerly-inherited `xhigh` down to this floor and collapses its variance. + +On top of the floor you pay the model's generation time (a function of output length). Progressive +output is not wired up **yet** (see "No real token streaming" above — it is achievable and planned), +so today a turn returns as one blob once generation completes. Note that streaming, when it lands, +will move the *first* byte earlier — it does **not** shorten the turn, and a consumer that needs the +complete answer gains nothing from it. + +**Use TUI mode for**: batch, background, and latency-insensitive work where the subscription pool is +the point. **Do not use it for**: anything a person is waiting on interactively, or any consumer with +a sub-5-second budget. Full measurements and methodology: +[`docs/plans/2026-07-13-tui-latency/`](docs/plans/2026-07-13-tui-latency/). + ### Monitoring drift via `/health` `GET /health` includes a `tui` block so you can poll for a silent billing-pool drift (the top risk after the 6/15 flip — a lost TTY flipping `cc_entrypoint` from `cli` to the metered `sdk-cli` pool would still return answers but burn metered credits). The block is **always present** (with `enabled:false` when TUI-mode is off): diff --git a/docs/plans/2026-07-13-tui-latency/README.md b/docs/plans/2026-07-13-tui-latency/README.md index 88c9a71..db8f10f 100644 --- a/docs/plans/2026-07-13-tui-latency/README.md +++ b/docs/plans/2026-07-13-tui-latency/README.md @@ -1,7 +1,9 @@ # TUI-mode latency: measured floor, and the four things worth fixing **Date**: 2026-07-13 -**Status**: findings + backlog (no code changed yet) +**Status**: findings + backlog. **Superseded in part** — see the dated update boxes below. +Item #1 shipped ([#156](https://github.com/dtzp555-max/ocp/pull/156)); item #2 is **dead** +([`streaming-spike.md`](streaming-spike.md)); item #4 measured, **no effect**; item #3 stands. **Measured on**: Mac mini / macOS 26.5.2 / Claude Code **v2.1.207** / Sonnet 5 / Claude Max subscription / **real-home mode** (no `CLAUDE_CODE_OAUTH_TOKEN`, no `OCP_TUI_HOME` in the service env) **Evidence**: [`measurements.jsonl`](measurements.jsonl) — **n=15** (3 configs × 5) · banner captures [`billing-banner.txt`](billing-banner.txt) · harness [`floor.sh`](floor.sh) @@ -47,6 +49,18 @@ All rows in [`measurements.jsonl`](measurements.jsonl); every number below is re before returning anything. There is no streaming path. The ~20 s delta between this harness's real TTFT and OCP's reported 30–32 s is exactly that. +> **⚠️ 2026-07-13 correction — this decomposition attributes the ~20 s to the wrong thing.** It was +> inferred from the external 30–32 s report, never measured *through* OCP. It has since been measured +> through a real OCP instance (TUI mode, `claude-sonnet-4-6`, the same ~1850-token prompt, n=5): +> **median 11.30 s** before [#156](https://github.com/dtzp555-max/ocp/pull/156), **9.55 s** after. +> Same-turn decomposition (baseline row `i=5`): **11.563 s** wall through OCP vs `turn_duration: +> 7.319 s` of CLI-internal time on that same turn → **OCP's own overhead ≈ 4.2 s** (n=1), **not +> ~20 s**. The rest of any larger number is the model *generating a long answer*, +> which the blocking wait does not cause and streaming would not shorten — it would only move the +> first byte earlier. The 30–32 s figure therefore reflects a much longer output (and/or the +> then-inherited `xhigh` effort), not 20 s of OCP dead time. See +> [`streaming-spike.md`](streaming-spike.md) § "What streaming would have bought". + --- ## ⚠️ Blocking constraint: `--bare` silently drops you off the subscription pool @@ -105,7 +119,28 @@ the effort level silently changes if the operator ever switches to env-token mod - **Risk**: none — banner confirms it stays on `Claude Max` (see `billing-banner.txt`). - ⚠️ Do **not** reach for `--bare` to shave boot: see above. -### 2. Real streaming instead of blocking on turn-terminal — **the big one (~20 s)** +### 2. Real streaming instead of blocking on turn-terminal — **ACHIEVABLE → [`streaming-spike.md`](streaming-spike.md)** + +> **2026-07-13 update — the prereq spike was run. The answer is YES, but not from either source this +> item guessed at.** (a) The transcript grows at *event* granularity (the whole answer lands in one +> line, ~0.3 s before terminal) — dead. (b) The pane is a **rendered** view whose `capture-pane` text +> no longer contains the answer's source bytes (`## `, `**`, code fences are gone) — dead, and worse +> than "lossy": it is *not the model's text*. **But there is a third source neither this backlog nor +> the first spike considered: `claude` fires a `MessageDisplay` hook carrying incremental, +> byte-faithful `delta`s of the raw reply.** Verified live on a plain interactive TUI spawn (no `-p`), +> banner `· Claude Max`: 7 fires spread across generation, `concat(deltas) === T` **byte-exactly** +> (579 == 579), `T.startsWith(S)` true at every step, `## ` / `**` / ```` ```javascript ```` all +> present in the deltas. Granularity is block-level (~5–7 chunks/answer), not token-level — plenty for +> SSE. **Build it.** +> +> ⚠️ Two corrections to this item as written: the **"~20 s" is wrong** (inferred from an external +> report, never measured through OCP — the same-turn decomposition puts OCP's own overhead at **~4 s**, +> n=1), and **streaming moves the first byte, not the last** — so a consumer needing the *complete* +> answer (the JSON-card case that motivated this) gains **nothing** from it. Build it for +> progressively-rendering consumers, not as a throughput win. +> +> Full evidence + implementer caveats (the hook is `forceSyncExecution` — claude BLOCKS on it): +> **[`streaming-spike.md`](streaming-spike.md)**. Original framing preserved below. Today `runTuiTurn` blocks on the transcript until the turn is *finished*. The pane is already rendering tokens incrementally the whole time — this harness proves you can observe first token @@ -132,7 +167,18 @@ the background) amortizes it to zero for any workload below the pool refill rate #148 — pooled panes must not look like zombies to the sweep. - Lower priority than #1 and #2: it is the smallest slice. -### 4. Trim the prefill — **probably not worth it; know the floor** +### 4. Trim the prefill — ~~probably not worth it~~ **MEASURED: no detectable benefit. Do not adopt.** + +> **2026-07-13 update.** `--exclude-dynamic-system-prompt-sections` was measured with the same +> harness (`floor.sh`, n=5, Sonnet 5, on top of `--effort low`): **TTFT median 6.39 s** +> (5.87–10.54 s) vs **6.17 s** (5.87–6.44 s) for `--effort low` alone — i.e. **0.22 s worse, inside +> the noise band**, with one worse outlier; dropping that outlier does not change the verdict. n=5 +> cannot prove "zero", only "no benefit detectable above noise" — but there is also a **mechanistic** +> reason not to expect one: `--help` says the flag *"Improves cross-user prompt-cache **reuse**"*, and +> **OCP is single-user** — there is no cross-user cache to share, so the flag has nothing to buy here. +> The banner stayed on `· Claude Max` (no billing-pool drop), but there is no win to bank. The ~6 s +> floor stands as stated below. Raw rows: [`prefill-spike-measurements.jsonl`](prefill-spike-measurements.jsonl). + After #1–#3, the floor is **~6 s**, and it does not go lower. `claude` always injects the full Claude Code system prompt + tool definitions (thousands to tens of thousands of prefill tokens) diff --git a/docs/plans/2026-07-13-tui-latency/messagedisplay-deltas.jsonl b/docs/plans/2026-07-13-tui-latency/messagedisplay-deltas.jsonl new file mode 100644 index 0000000..3dc4f14 --- /dev/null +++ b/docs/plans/2026-07-13-tui-latency/messagedisplay-deltas.jsonl @@ -0,0 +1,7 @@ +{"hook_event_name": "MessageDisplay", "index": 0, "final": false, "delta": "## Mutex\n\n"} +{"hook_event_name": "MessageDisplay", "index": 1, "final": false, "delta": "A **mutual exclusion lock** prevents concurrent access to a shared resource, ensuring only one thread runs the critical section at a time.\n\n"} +{"hook_event_name": "MessageDisplay", "index": 2, "final": false, "delta": "- Acquiring a locked mutex blocks the caller until the current holder releases it.\n"} +{"hook_event_name": "MessageDisplay", "index": 3, "final": false, "delta": "- Failing to release a mutex causes a deadlock, freezing all waiting threads.\n\n```javascript\nconst { Mutex } = require('async-mutex');\n\nconst mutex = new Mutex();\n"} +{"hook_event_name": "MessageDisplay", "index": 4, "final": false, "delta": "let counter = 0;\n\nasync function increment() {\n const release = await mutex.acquire();\n try {\n"} +{"hook_event_name": "MessageDisplay", "index": 5, "final": false, "delta": " counter++; // only one caller here at a time\n } finally {\n release();\n }\n}\n"} +{"hook_event_name": "MessageDisplay", "index": 6, "final": true, "delta": "```"} diff --git a/docs/plans/2026-07-13-tui-latency/prefill-spike-measurements.jsonl b/docs/plans/2026-07-13-tui-latency/prefill-spike-measurements.jsonl new file mode 100644 index 0000000..88391a7 --- /dev/null +++ b/docs/plans/2026-07-13-tui-latency/prefill-spike-measurements.jsonl @@ -0,0 +1,5 @@ +{"i":1,"tag":"effort-low-exclude-dynamic","model":"claude-sonnet-5","extra_args":"--effort low --exclude-dynamic-system-prompt-sections","prompt_chars":7451,"boot_ms":934,"ttft_ms":5867,"complete_ms":9953} +{"i":2,"tag":"effort-low-exclude-dynamic","model":"claude-sonnet-5","extra_args":"--effort low --exclude-dynamic-system-prompt-sections","prompt_chars":7451,"boot_ms":1275,"ttft_ms":6388,"complete_ms":9874} +{"i":3,"tag":"effort-low-exclude-dynamic","model":"claude-sonnet-5","extra_args":"--effort low --exclude-dynamic-system-prompt-sections","prompt_chars":7451,"boot_ms":874,"ttft_ms":10537,"complete_ms":11782} +{"i":4,"tag":"effort-low-exclude-dynamic","model":"claude-sonnet-5","extra_args":"--effort low --exclude-dynamic-system-prompt-sections","prompt_chars":7451,"boot_ms":1170,"ttft_ms":6379,"complete_ms":9947} +{"i":5,"tag":"effort-low-exclude-dynamic","model":"claude-sonnet-5","extra_args":"--effort low --exclude-dynamic-system-prompt-sections","prompt_chars":7451,"boot_ms":1329,"ttft_ms":6443,"complete_ms":9884} diff --git a/docs/plans/2026-07-13-tui-latency/streaming-spike.md b/docs/plans/2026-07-13-tui-latency/streaming-spike.md new file mode 100644 index 0000000..e2b4854 --- /dev/null +++ b/docs/plans/2026-07-13-tui-latency/streaming-spike.md @@ -0,0 +1,256 @@ +# Backlog #2 (real streaming): **achievable** — via the `MessageDisplay` hook + +**Date**: 2026-07-13 +**Status**: prereq-spike result. **Streaming IS achievable on the TUI path**, byte-faithfully, on the +subscription pool. Three obvious sources are dead ends; a fourth one works. +**Scope**: answers the prereq spike that [`README.md`](README.md) § "Backlog #2" demanded *before* any +streaming design: + +> **Prereq spike (do this before designing anything)**: does the transcript JSONL grow *during* a +> turn, or only at the end? If only at the end, (a) is dead and you are stuck with (b). + +The answer: **(a) is dead, (b) is dead — and you are not stuck with either.** The CLI exposes its own +streaming interface as a **hook**, which the backlog did not consider. + +**Measured on**: Mac mini / Claude Code **v2.1.207** / Sonnet 4.6 + Sonnet 5 / Claude Max / +real-home mode. Every claim below is reproducible from the commands given. + +> **Honesty note on how this document was produced.** Its first version concluded the exact opposite — +> "streaming is not achievable; the CLI exposes no byte-faithful incremental source" — and was **wrong**. +> An adversarial reviewer, commissioned specifically to *refute* it, found `MessageDisplay` on a second +> pass; its own first pass had enumerated the hook registry with a truncated grep (it reported 21 +> events — there are **30**). Both the wrong conclusion and its refutation are preserved here, because +> "we checked, it's impossible" is the most expensive kind of claim to get wrong: it closes a door and +> nobody re-opens it. + +--- + +## ✅ The source that works: the `MessageDisplay` hook + +`claude` fires a **`MessageDisplay`** hook as it renders each block of the assistant's reply. The +payload carries the **raw markdown source** of an incremental `delta`, plus a monotonic `index` and a +`final` flag: + +```json +{ "hook_event_name": "MessageDisplay", + "turn_id": "6cb31d21-…", "message_id": "84ab9832-…", + "index": 0, "final": false, "delta": "## Mutex\n\n" } +``` +*(payload also carries `session_id`, `transcript_path`, `prompt_id`, `cwd`)* + +Registered as an ordinary command hook via `--settings` on a **plain interactive TUI spawn** (no `-p`, +no `--bare`), `claude-sonnet-4-6`, `--effort low`. Banner verified: +`▝▜█████▛▘ Sonnet 4.6 with low effort · Claude Max` — **subscription pool, not metered billing**. + +One live turn — 7 fires, spread across generation: + +``` +index=0 final=false len= 10 '## Mutex\n\n' +index=1 final=false len= 140 'A **mutual exclusion lock** prevents concurrent access to a shar…' +index=2 final=false len= 83 '- Acquiring a locked mutex blocks the caller until the current h…' +index=3 final=false len= 163 '- Failing to release a mutex causes a deadlock, freezing all wai…' +index=4 final=false len= 96 'let counter = 0;\n\nasync function increment() {\n const release =…' +index=5 final=false len= 84 ' counter++; // only one caller here at a time\n } finally {\n …' +index=6 final=true len= 3 '```' +``` + +**Every invariant a proxy needs — all hold:** + +| requirement | result | +|---|---| +| **byte-faithful** — deltas are the model's *source*, not the rendered pane | ✅ `## `, `**`, ```` ```javascript ```` all present in the deltas | +| **exactness** — `concat(deltas) === T` (the transcript-authoritative text) | ✅ **true**, 579 == 579 bytes | +| **prefix-stable** — `T.startsWith(concat(deltas[0..n]))` at every n | ✅ **true at all 7 steps** | +| **incremental** — arrives during generation, not at the end | ✅ 7 fires spread across the turn | +| **no `-p`** — stays out of the metered `sdk-cli` pool | ✅ plain interactive TUI | +| **subscription pool** | ✅ banner `· Claude Max` | + +This is exactly the contract a streaming design needs: deltas forward straight into SSE +`delta.content` chunks, and the transcript's final text `T` stays a cheap end-of-turn assertion +(`concat === T`) instead of a reconciliation problem. + +### Caveats for the implementer + +- **Block-level granularity, not token-level** — the hook fires **once per rendered block** (roughly one + per paragraph / list item / code block), so the chunk count **scales with answer length**: 7 fires for a + ~600-byte answer, **18 for a ~2 KB one**. Plenty for SSE (`delta.content` has no minimum size), but do + not promise token-by-token output, and do not hard-code any assumption about chunk count. +- **🔴 The sink MUST be keyed by `session_id` — this is live TODAY, not a future concern.** + `OCP_TUI_MAX_CONCURRENT` defaults to **2**, so **two `claude` processes already run concurrently**. One + hook command writing to one shared sink would **interleave deltas from two different turns into one + stream** — request A's client receiving request B's text, the worst failure a proxy can have, and one a + single-request test will never surface. The payload carries `session_id` (and `turn_id` / `message_id`), + so demux is easy: derive the sink path from `session_id` (`/.jsonl`) and read only your + own turn's file. This *also* keeps the design **warm-pool compatible**, because a pre-booted pane's + session-id is fixed at boot — one static hook script serves every pane. **Test it with ≥2 concurrent + streaming requests carrying distinguishable prompts and assert zero cross-contamination.** +- **⚠️ `forceSyncExecution: true` in the hook's source — `claude` BLOCKS on the hook.** A slow hook + adds latency to *every* delta. The hook must write and exit immediately (e.g. write to a FIFO / unix + socket that OCP reads; never work inline). **Measure the added per-delta latency.** +- **Thinking blocks appear to be excluded — but this is NOT yet stress-tested. Verify before shipping.** + The exclusion is inferred from `content.map(c => c.type === "text" ? c.text : "")` — but that snippet is + from the **`final:true`** call site, not the incremental one. Four live turns (incl. two at `--effort + high`) showed no thinking text in any delta and `concat === T` held — **but each transcript's thinking + block was empty (`thinking:""`, 0 chars)**, so the exclusion was never actually stressed. **The failure + mode is severe**: if thinking deltas *do* fire on some config (Opus, `xhigh`), `concat(deltas) !== T` + **and OCP streams the model's private reasoning to the caller**. The end-of-turn `concat === T` assertion + would *detect* that but **cannot prevent** it — SSE deltas cannot be un-sent. **Before shipping, run a + turn on a model+effort that produces substantive thinking** (a hard reasoning prompt on Opus / `xhigh`) + and confirm both (a) no thinking text in any delta and (b) `concat === T` still holds. +- OCP already owns the spawn (isolated HOME, its own flags), so injecting `--settings` with a + `MessageDisplay` hook sits inside the existing architecture. +- **`ALIGNMENT.md`**: this consumes `claude`'s **own** hook surface as emitted — forwarding, not + inventing. Not a new endpoint, not a fabricated protocol. (Class B / ADR 0007 — the TUI spawn is + OCP-owned; no `cli.js` citation applies.) + +### Reproduce in 60 seconds + +```bash +# hook script: append the payload (arrives on stdin) and exit immediately +printf '#!/bin/bash\ncat >> "$MD_LOG"; printf "\\n" >> "$MD_LOG"; exit 0\n' > /tmp/h.sh && chmod +x /tmp/h.sh +echo '{"hooks":{"MessageDisplay":[{"hooks":[{"type":"command","command":"MD_LOG=/tmp/deltas.jsonl /tmp/h.sh"}]}]}}' > /tmp/s.json + +# plain interactive claude in tmux (prefix NOT ocp-tui-*, and never kill-server) +tmux new-session -d -s md-probe -x 220 -y 50 \ + "claude --model claude-sonnet-4-6 --effort low --session-id $(uuidgen) --settings /tmp/s.json" +# …wait for '? for shortcuts', paste a markdown-producing prompt, press Enter… + +jq -r '"\(.index) \(.final) \(.delta|@json)"' /tmp/deltas.jsonl # incremental raw-markdown deltas +# then assert: concat(deltas) == extractLatestAssistantText(.jsonl) +``` + +--- + +## The three dead ends (still worth knowing — they say what NOT to build) + +### (a) Incremental transcript reads — **dead: event granularity, not token granularity** + +The transcript JSONL *does* grow during a turn, but one **whole event at a time**; the assistant's text +event is written as **one complete line**, appearing only ~0.3 s before the terminal `turn_duration`. + +Observed (session `efd5b161`, `turn_duration: 7319 ms`): + +``` + #6 t+0.0s type=user (the prompt) + #15 t+4.7s type=assistant blocks=thinking + #16 t+7.0s type=assistant blocks=text ← the ENTIRE answer, in one line + #21 t+7.3s type=system subtype=turn_duration ← terminal +``` + +Cross-checked at **20 ms polling + `fs.watch`** (25× finer): a partial line **never touches disk** — +one write, `+1` line, carrying the complete answer. Also forced with the undocumented +`CLAUDE_CODE_INCLUDE_PARTIAL_MESSAGES=1`: still 1 assistant event, 0 partials (interactive mode has no +stream-json *sink* for it to write to). + +**The transcript is still needed** — as the terminal-turn signal, as the authoritative `concat === T` +check, and as the input to the existing honesty gates (auth-banner detection, `truncated`). It is just +not the *streaming* source. + +### (b) `tmux capture-pane` diffing — **dead: the pane is a RENDERED view, not the text** + +The backlog expected to fall back to this, calling it "lossy … (wrapping, scrollback, spinner lines)". +The loss is far worse than formatting noise: **the pane does not contain the answer's source bytes at +all.** The TUI *renders* markdown, and `capture-pane -p` strips the ANSI that rendering produced. + +Same turn, same lines: + +``` +TRANSCRIPT (authoritative T): PANE (capture-pane -p -J -S -500): + '## Semaphore' '⏺ Semaphore' ← heading marker gone + '' '' + 'A **semaphore** is a synchro…' ' A semaphore is a synchro…' ← bold markers gone, indented +``` + +| token in the answer | in `T` | in the pane's answer region | +|---|---|---| +| `## ` (ATX heading) | yes | **no** — rendered as `⏺` | +| `**` (bold markers) | yes | **no** — rendered to ANSI bold, then stripped by `-p` | +| ` ```javascript ` (fence + language) | yes | **no** — fence and language tag both gone | +| `- ` (list item) | yes | yes | + +*(A literal `**` does appear elsewhere in the pane — in the **prompt echo**, because the prompt asked +for bold. Not in the answer.)* + +**`capture-pane -e` (keeping the ANSI) does not rescue it — the inverse is provably non-unique.** +With `T` = ``"## Alpha\n\n**bravo**\n\n```javascript\nlet x=1;\n```"``: + +``` +⏺\e[39m \e[1mAlpha\n\n\e[0m \e[1mbravo\n\n\e[0m \e[34mlet\e[39m x=\e[32m1\e[39m; +``` + +`## Alpha` → **SGR 1 (bold)**. `**bravo**` → **SGR 1 (bold)**. *Identical ANSI* — an H2 and a bold span +are indistinguishable, never mind `**` vs `__`. The fence and its `javascript` tag are consumed by the +syntax highlighter into colours; recovering the tag would mean inverting a highlighter, and +`let x=1;` is valid in several languages. + +So `T.startsWith(paneText)` is **false** — raw and indent-stripped, on essentially every markdown +answer. A proxy streaming pane text would be streaming **something the model did not say**. With +`MessageDisplay` available there is no reason to go near it. + +### (c) `--debug-file` — **dead: it logs stream *timing*, never stream *content*** + +Worth stating precisely, because a casual check misleads in **both** directions here. + +The default log level is `debug`, which **suppresses every `verbose` site**. Raise it and per-chunk +lines *do* appear, spread across generation: + +```bash +CLAUDE_CODE_DEBUG_LOG_LEVEL=verbose claude --debug-file /tmp/d.log … +``` +``` +05:51:11.088 [VERBOSE] [shoji-engine] yield stream_event/- ← 16 of these, mid-turn, +05:51:11.537 [VERBOSE] [shoji-engine] yield stream_event/- over ~3.9 s of generation +05:51:15.192 [DEBUG] [shoji-engine] turn 1 end (usage in=575 out=255 api=6736ms stop=end_turn resultLen=857) +``` + +**But they carry no payload** — the format is `yield /`, a bare presence marker. Run with +no category filter (i.e. all categories) at verbose level: `content_block_delta` = **0**, `text_delta` = +**0**, `content_block_start` / `message_start` = **0**. The only byte-exact text in the log is the +end-of-turn `Stop` hook payload (`"last_assistant_message":"## Title\n\n**alpha bravo charlie**"`) — +transcript granularity. The log tells you **when** tokens arrive, never **what** they are. It is also +~2.7 MB per turn. + +### Also checked, also not the answer + +| candidate | outcome | +|---|---| +| `--output-format stream-json` (the one interface that emits `text_delta`) | **requires `--print`/`-p`** → `cc_entrypoint=sdk-cli` → the **metered** credit pool, which is exactly what TUI mode exists to avoid. Reproduced live. | +| `--input-format stream-json` | `Error: --input-format=stream-json requires output-format=stream-json` → same gate. | +| `CLAUDE_CODE_INCLUDE_PARTIAL_MESSAGES=1` (undocumented) | No stream-json sink in interactive mode → no partials. Banner stayed `· Claude Max`. | +| `sessionMirror` (undocumented) | Gated on `outputFormat === "stream-json"` → the `-p` family. | +| `--sdk-url` (hidden) | Forces stream-json + non-interactive → `sdk-cli`. *(inferred from the minified bundle; not banner-tested)* | +| `~/.claude/sessions/.json` | Registry metadata only (`{pid, sessionId, cwd, status, version, entrypoint:"cli", kind:"interactive"}`). No assistant text. *(Its `entrypoint:"cli"` incidentally confirms the TUI path stays on the subscription pool.)* | +| `~/.claude/history.jsonl` | User prompts only; the answer text is absent. | +| Asking the model to emit plain text (so the pane renders faithfully) | Would mean **mutating the caller's prompt** — a correctness violation for a proxy, and still not byte-faithful (wrapping + indent remain). Rejected. | + +--- + +## Value: what streaming actually buys (read before building) + +Streaming is *possible*. Whether it is *worth it* depends on the consumer, and the honest answer is +uncomfortable: + +- **Streaming never makes the answer arrive sooner. It moves the *first* byte, not the *last*.** The + final token lands at the same wall-clock moment either way. +- So a consumer that must have the **complete** answer before it can act — e.g. one parsing a structured + JSON reply, **which is exactly the 知音 AI use case that motivated this entire investigation** — gains + **nothing at all**. Only a **progressively-rendering** consumer (a chat UI) gains. + +And the number the backlog attached to this item was wrong: + +- The backlog's "~20 s" was inferred from an external 30–32 s report, **never measured through OCP**. + Measured through a real OCP instance (TUI mode, `claude-sonnet-4-6`, ~1850-token prompt, n=5): + **median 11.30 s** before [#156](https://github.com/dtzp555-max/ocp/pull/156), **9.55 s** after. +- **Same-turn decomposition** (baseline row `i=5`): **11.563 s** wall through OCP vs `turn_duration: + 7.319 s` of CLI-internal time on that same turn → **OCP's own overhead ≈ 4.2 s** (n=1, baseline + `effort=high` config). *Caveats*: n=1; and `turn_duration` is the CLI's internal duration of an + **OCP-driven** turn, not a separate "native" baseline. Do **not** subtract this `effort=high` 7.3 s + from the `effort=low` 9.55 s median — a low-effort turn generates faster, so mixing them + *understates* the overhead. +- So OCP's own overhead is **single-digit seconds**, not ~20 s. The rest of any large number is the + model generating a long answer — which streaming hides but does not shorten. + +**Recommendation**: build it — the contract is clean and the cost is small — but size the expectation +honestly. It is a *perceived-latency* feature for progressively-rendering consumers, not a throughput +win, and it does not move the **~6 s TTFT floor** ([`README.md`](README.md)) that rules TUI mode out for +interactive-latency consumers regardless.