From fc63b8a49a3fe03e10e4da99143dce918433a913 Mon Sep 17 00:00:00 2001 From: dtzp555 Date: Mon, 13 Jul 2026 16:04:12 +1000 Subject: [PATCH] =?UTF-8?q?docs:=20fold=20in=20adversarial=20review=20?= =?UTF-8?q?=E2=80=94=20correct=20the=20debug-log=20reasoning=20+=20the=20o?= =?UTF-8?q?verhead=20number?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 --- README.md | 4 +- docs/plans/2026-07-13-tui-latency/README.md | 23 ++-- .../2026-07-13-tui-latency/streaming-spike.md | 115 ++++++++++++++---- 3 files changed, 107 insertions(+), 35 deletions(-) diff --git a/README.md b/README.md index 30a14da..ea3fd9d 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 — and it cannot be added.** 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. This is **structural, not a missing feature**: interactive `claude` exposes no byte-faithful incremental output. Its three observables are a *rendered* terminal (the pane's text has markdown source markers — `## `, `**`, code fences — stripped by rendering, so it is not the model's text), a transcript written at *event* granularity (the whole answer lands in one line ~0.3 s before the turn ends), and a debug log also written at end-of-turn. The one interface that emits token deltas, `--output-format stream-json`, requires `-p` — the metered-billing path TUI mode exists to avoid. Evidence: [`docs/plans/2026-07-13-tui-latency/streaming-spike.md`](docs/plans/2026-07-13-tui-latency/streaming-spike.md). +- **No real token streaming — and it cannot be added.** 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. This is **structural, not a missing feature**: interactive `claude` exposes no byte-faithful incremental output. Its three observables are a *rendered* terminal (the pane's text has markdown source markers — `## `, `**`, code fences — stripped by rendering, so it is not the model's text), a transcript written at *event* granularity (the whole answer lands in one line ~0.3 s before the turn ends), and a debug log that reports *when* tokens arrive but never *what* they are (its mid-turn events carry no text payload at any verbosity). The one interface that emits token deltas, `--output-format stream-json`, requires `-p` — the metered-billing path TUI mode exists to avoid. 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. @@ -1050,7 +1050,7 @@ path, stated plainly so you can rule it out before building on it: |---|---| | **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 | ~2–4 s | +| 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 diff --git a/docs/plans/2026-07-13-tui-latency/README.md b/docs/plans/2026-07-13-tui-latency/README.md index 4e48951..18886b7 100644 --- a/docs/plans/2026-07-13-tui-latency/README.md +++ b/docs/plans/2026-07-13-tui-latency/README.md @@ -52,9 +52,10 @@ 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 — -> against a native `turn_duration` of ~7.3 s for a comparable turn. So **OCP's own overhead above the -> CLI is ~2–4 s, not ~20 s.** The rest of any larger number is the model *generating a long answer*, +> **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 @@ -124,7 +125,9 @@ the effort level silently changes if the operator ever switches to env-token mod > grows at *event* granularity (the whole answer lands in one line, ~0.3 s before terminal), and the > pane is a **rendered** view whose `capture-pane` text no longer contains the answer's source bytes > (`## `, `**`, code fences are gone) — so no pane-derived stream can be reconciled with the -> authoritative text. A third source (`--debug-file`) is byte-exact but also end-of-turn. +> authoritative text. A third source (`--debug-file`) does emit mid-turn stream events at +> `CLAUDE_CODE_DEBUG_LOG_LEVEL=verbose` — but they carry **timing only, no text payload** (0 +> `text_delta` at any verbosity); its only byte-exact text is the end-of-turn `Stop` hook payload. > `--output-format stream-json`, the only interface that emits token deltas, requires `-p` — the > metered-billing path that TUI mode exists to avoid. **True token streaming is not achievable on the > TUI path**; OCP's TUI SSE is replay-only. Note also that streaming would never have shortened a @@ -159,13 +162,17 @@ 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~~ **MEASURED: no effect. Do not adopt.** +### 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. **zero marginal -> benefit**, within noise and with one worse outlier. 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. +> (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 diff --git a/docs/plans/2026-07-13-tui-latency/streaming-spike.md b/docs/plans/2026-07-13-tui-latency/streaming-spike.md index d2197af..a8e2d86 100644 --- a/docs/plans/2026-07-13-tui-latency/streaming-spike.md +++ b/docs/plans/2026-07-13-tui-latency/streaming-spike.md @@ -66,15 +66,29 @@ PANE (the same turn): ' - Tracks available "permits" and decrements the count when a thread acquires access, …' ``` -Token-presence check over the whole final frame: +Token-presence check **over the pane's answer region** (the prompt echo above it is excluded — it +does contain a literal `**`, because the prompt itself asked for bold): -| token in the answer | in transcript `T` | in pane | +| token in the answer | in transcript `T` | in pane's answer region | |---|---|---| | `## ` (ATX heading) | yes | **no** — rendered as `⏺` | | `**` (bold markers) | yes | **no** — rendered as ANSI bold, then stripped by `-p` | | ` ```javascript ` (fence + language) | yes | **no** — fence gone, language tag gone | | `- ` (list item) | yes | yes | +**`capture-pane -e` (keep the ANSI) does not rescue it — the inverse is provably non-unique.** +Minimal case, transcript `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 (`\e[34mlet`); recovering the tag would mean inverting a +highlighter, and `let x=1;` is valid in several languages. Marker check on the `-e` capture: `## `, +`**`, ```` ``` ````, ```` ```javascript ```` — **all absent**. + Consequence for any design built on pane diffing: with `S` = text streamed from the pane and `T` = the transcript's authoritative text, the prefix invariant **`T.startsWith(S)` is false** — both raw and with the 2-space indent stripped. Not "sometimes, on redraw" — **on essentially every answer @@ -91,31 +105,66 @@ A proxy that streams pane text is streaming **something the model did not say**. a quality trade-off, it is a correctness violation (`ALIGNMENT.md` Core Principle: forward what `cli.js` emits; do not invent). -### (c) `--debug-file` — **dead: byte-exact, but only at end-of-turn** +### (c) `--debug-file` — **dead: it logs stream *timing*, never stream *content*** -Not considered in the original backlog; checked for completeness because it is the only other -observable claude writes. +Not considered in the original backlog; checked because it is the only other observable claude writes. -`claude --debug-file ` does contain the **byte-exact raw markdown** — but only inside -**end-of-turn hook payloads**: +**There ARE mid-turn stream events in the debug log** — this is the one place a casual check +misleads, so it is worth stating precisely. The default log level is `debug`, which **suppresses +every `verbose` site**. Raise it and per-chunk lines appear, spread across the generation: +```bash +CLAUDE_CODE_DEBUG_LOG_LEVEL=verbose claude --debug-file /tmp/d.log … ``` -[DEBUG] Hooks: Parsed initial response: {… "hook_event_name":"Stop", … - "last_assistant_message":"## Title\n\n**alpha bravo charlie**" …} +``` +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/- spread over ~3.9 s of generation +… +05:51:14.910 [VERBOSE] [shoji-engine] yield assistant/- +05:51:15.192 [DEBUG] [shoji-engine] turn 1 end (usage in=575 out=255 api=6736ms stop=end_turn resultLen=857) ``` -Note `## ` and `**` survive here — this is the real text. But it arrives with the `Stop` hook, i.e. -the same end-of-turn granularity as the transcript. Grepping the log for streaming events -(`content_block_delta` / `text_delta`) finds **zero**. The log is also ~2.7 MB per turn, which rules -it out as a production mechanism regardless. +**But they carry no payload.** The format is `yield /` — a bare presence marker. At +verbose level, with every category filter, the log contains: + +| event | count | +|---|---| +| `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**"` — note `## ` and `**` survive, so +this *is* the real text), which is the same granularity as the transcript. So the debug log gives you +**when** tokens arrive, never **what** they are. It is also ~2.7 MB per turn. + +*(An incremental "a token arrived" signal with no token in it cannot feed an SSE `delta.content`.)* + +### Everything else that could plausibly carry tokens — also checked, also dead + +An adversarial second pass (independent reviewer, tasked with *refuting* this document) enumerated +the rest of the search space rather than sampling it. Nothing survived: + +| candidate | how it dies | +|---|---| +| **Hooks** — is there a per-message/per-chunk hook? | The hook registry was enumerated from the shipped binary: `PreToolUse, PostToolUse, PostToolUseFailure, PostToolBatch, Notification, UserPromptSubmit, UserPromptExpansion, SessionStart, SessionEnd, Stop, StopFailure, SubagentStart, SubagentStop, PreCompact, PostCompact, PermissionRequest, PermissionDenied, Setup, TeammateIdle, TaskCreated, TaskCompleted`. **No streaming/per-chunk hook exists.** | +| `CLAUDE_CODE_INCLUDE_PARTIAL_MESSAGES=1` (undocumented env twin of the flag; bypasses flag validation) | Ran live in a TUI turn: transcript still had **1** assistant event, **0** partials. Interactive mode has no stream-json *sink* for it to write to. Banner stayed `· Claude Max`. | +| `sessionMirror` (undocumented) | Gated on `outputFormat === "stream-json"` → the `-p` family. | +| `--sdk-url` (hidden) | Forces stream-json + non-interactive → `sdk-cli` (metered pool). | +| `--input-format stream-json` | Live: `Error: --input-format=stream-json requires output-format=stream-json` → which requires `--print`. And it is an *input* format regardless. | +| `~/.claude/sessions/.json` (modified mid-turn) | Registry metadata only: `{pid, sessionId, cwd, status, version, entrypoint:"cli", kind:"interactive"}`. **No assistant text.** (Its `entrypoint:"cli"` is incidental independent confirmation that the TUI path stays on the subscription pool.) | +| `~/.claude/history.jsonl` (modified mid-turn) | Keys: `[display, pastedContents, timestamp, project, sessionId]` — **user prompts only**; the answer text is absent. | +| `~/.claude/settings.json` | No key for partial/streaming output. | +| **Ask the model to emit plain text** (so the pane render is faithful) | Would require OCP to **mutate the caller's prompt** — a correctness violation for a proxy (`ALIGNMENT.md`: forward what `cli.js` emits; do not invent), it would corrupt callers who legitimately want markdown or JSON, and it *still* would not be byte-faithful (the TUI keeps wrapping and 2-space indenting). Rejected. | --- ## What this means **True token streaming is not achievable on the TUI path**, at any effort, with any flag combination -available in claude 2.1.207. The three observables are: a rendered terminal (lossy beyond repair), a -transcript written at event granularity (end-of-turn), and a debug log written at end-of-turn. +available in claude 2.1.207. The three observables are: a rendered terminal (lossy beyond +repair), a transcript written at event granularity (the answer lands whole, end-of-turn), and a debug +log that reports *when* tokens arrive but never *what* they are. `--output-format stream-json` — the one interface that *does* emit `text_delta` events — works **only with `--print`/`-p`**, and the `-p` path is precisely what TUI mode exists to avoid (it is classified `cc_entrypoint=sdk-cli` → the metered credit pool, not the subscription pool). The @@ -135,15 +184,28 @@ Worth stating plainly, because it changes the value calculus: gains **nothing at all** from streaming. Only a progressively-rendering consumer (a chat UI) gains. - The backlog's "~20 s" for item #2 was inferred from an external report of 30–32 s, not 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 PR #156, **9.55 s** after — against a native - `turn_duration` of ~7.3 s for a comparable turn. So OCP's own overhead over the CLI is roughly - **2–4 s**, not 20 s; the rest of any large number is the model generating a long answer, which - streaming hides but does not shorten. (A 30 s turn is a 30 s turn either way — the last token - lands at the same wall-clock moment.) + prompt, n=5): **median 11.30 s** before PR #156, **9.55 s** after. + + **Same-turn decomposition** (the honest form — one turn, both numbers): baseline row `i=5` took + **11.563 s** end-to-end through OCP, and that same turn's transcript records + `turn_duration: 7.319 s` of CLI-internal time. → **OCP's own overhead ≈ 4.2 s** (n=1, baseline + `effort=high` config). Not 20 s. + + Two caveats, stated so the number is not over-trusted: this is **n=1**, and `turn_duration` is the + *CLI's* internal duration on an **OCP-driven** turn (it is not a "native, non-OCP" baseline — the + same interactive `claude` is doing the work either way). Do **not** subtract this 7.3 s + (`effort=high`) from the 9.55 s `effort=low` median: a low-effort turn generates faster, so its own + `turn_duration` would be lower, and mixing the two would *understate* the overhead. There is no + `turn_duration` sample for the `effort=low` config. + + Either way the direction is settled: OCP's overhead is **single-digit seconds**, not the ~20 s the + plan assumed. The rest of any large number is the model generating a long answer — which streaming + hides but does not shorten. (A 30 s turn is a 30 s turn either way; the last token lands at the same + wall-clock moment.) The honest remaining levers on the TUI path are therefore: the **~6 s TTFT floor** (immovable — see [`README.md`](README.md)), the **generation time** (a function of output length — not OCP's to -optimize), and OCP's **own 2–4 s of overhead** (per-request cold boot ≈1 s → backlog #3 warm pool; +optimize), and OCP's **own ~4 s of overhead** (n=1 same-turn decomposition; per-request cold boot ≈1 s → backlog #3 warm pool; plus readiness/paste/transcript poll granularity). --- @@ -174,10 +236,13 @@ plus readiness/paste/transcript poll granularity). # answer region against extractLatestAssistantText() over the session's transcript JSONL. # Expect: T.startsWith(paneText) === false, '## ' and '**' and '```' absent from the pane. -# (c) debug log -claude --model claude-sonnet-5 --session-id "$(uuidgen)" --effort low --debug-file /tmp/d.log -grep -cE 'content_block_delta|text_delta' /tmp/d.log # → 0 -grep -o 'last_assistant_message":"[^"]*' /tmp/d.log # → byte-exact text, at Stop-hook time +# (c) debug log — NOTE: default level is `debug`, which SUPPRESSES the verbose stream sites. +# Raise it, or you will wrongly conclude there are no mid-turn events at all. +CLAUDE_CODE_DEBUG_LOG_LEVEL=verbose \ + claude --model claude-sonnet-5 --session-id "$(uuidgen)" --effort low --debug-file /tmp/d.log +grep -c 'yield stream_event' /tmp/d.log # → 16 (mid-turn — timing exists!) +grep -cE 'content_block_delta|text_delta' /tmp/d.log # → 0 (…but no text payload, ever) +grep -o 'last_assistant_message":"[^"]*' /tmp/d.log # → byte-exact text, only at Stop-hook time ``` Banner check (mandatory for every spawn-flag change, per [`billing-banner.txt`](billing-banner.txt)):