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` (`