Hook latency: remaining work after #2002

[Soph]

Follow-up to #2002, which fixed the tail of hook latency but not the median. Filing the
measured state so the remaining work is picked up from evidence rather than re-derived.

What #2002 fixed

Profiling createRedactedBlobFromFile put redaction at 99.7% of the checkpoint blob
write (git object writing was 174ms of a 66.7s pass on 70MB), and the CPU profile put
82% of that in betterleaks' regex ruleset. full.jsonl holds the full session and was
re-redacted from byte zero every checkpoint, so a session with N checkpoints re-redacted
O(N²) bytes — which is also what inflates the multi-GB packs.

Sharding plus prefix reuse took a 14-checkpoint session growing to 70MB from ~66s to
~2.0s on the final Stop.

What is still open

1. ~~The ~3s p50 floor is unexplained~~ — ANSWERED, see the re-measure below

It was substantially the redaction path, and #2002 fixed it: population p50 2326ms →
1103ms, with write_temporary_checkpoint and redact_transcript gone from slow traces
entirely. Evidence and method are in the re-measure section.

Kept for the ruling-out work, which stays useful if the floor ever returns: it was not
the transcript-flush maxWait (its warning appears 0 times in real logs), the
trail-enablement refresh (detached subprocess by design), git-refs vs git-branch backend,
telemetry, checkpoint history, authentication, or local_dev. Size was not the driver
either — stop was flat across a 235× range of pack size, and 8KB → 1.2MB of transcript
added only ~125ms. The original distribution was bimodal with a hard floor at ~3s and a
near-empty 2500-2999ms gap beneath it, which is what made a conditional timeout look more
likely than variable work.

2. process_sessions — post-commit condensation

Dominant step in 27 of 93 slow traces. Independently confirms
docs/architecture/commit-hook-perf-analysis.md:
~73–103ms per accumulated session, N sessions per commit, PostCommit dominating. That doc
already lists concrete fixes (batch condensation into one commit, prune stale ENDED
sessions, skip the orphan check for sessions with LastCheckpointID). Nothing has been
done. Probably the largest remaining win.

2b. The compact transcript is generated twice per Stop

writeCompactTranscript has two call sites — checkpoint/persistent.go:1092 (checkpoint
write) and :2069 (Stop finalize rewrite) — and compact.FullWithBoundary compacts the
whole session each time. Measured at 457ms + 447ms = 904ms of a 2505ms Stop, which
makes it the largest single item in a Stop now that redaction is fixed.

Same shape as the problem #2107 just solved, and possibly the same remedy. Found during the
2026-08-23 re-measure, not from first principles — it only became visible once redaction
stopped dominating.

3. The transcript-flush sentinel is dead code costing a fixed ~520ms per Stop

waitForTranscriptFlush waits for a hook_progress transcript entry containing
"hooks claude-code stop". Claude Code no longer writes it — 0 occurrences across 40
real transcripts. So it always falls through to settle-on-stability, which structurally
cannot return before quietWindow (500ms) + one 50ms poll.

There is nothing to revive: what Claude Code writes now is
{"type":"system","subtype":"stop_hook_summary"}, emitted after the hook returns (it
reports the hook's own durationMs), so waiting on it would deadlock. Measured separately:
the final assistant entry lands 33ms before the hook starts, so the transcript is already
complete when the wait begins.

Needs a decision, not more investigation — shortening the window trades against reading a
truncated transcript, which is why it exists. Suggested shape: return as soon as the size
is stable across two polls and the last line parses as complete JSON.

4. Prefix reuse covers only the shadow write — DONE in #2107

Condensation and the Stop finalize rewrite now reuse prefixes too, via
checkpoint.RedactTranscriptCached. Promoted ahead of the rest because it stopped being
latency and became breakage: a coworker on a 65MB Codex rollout hit Codex's 30s Stop-hook
timeout (30.203s, process killed, finalize rewrite left incomplete).

Two things found while doing it, both worth knowing:

• A git blob is not a free place to cache bytes. The first cut stored the reused prefix
  as a blob, on the assumption git would dedup it. go-git deflates the whole payload before
  dotgit discovers the object exists — dedup saves the rename, not the compression — so it
  cost ~1-2s of zlib per checkpoint. Worse, the store chunks at agent.MaxChunkSize (50MB),
  so above that the whole-transcript blob matches no chunk, is never deduped, and lingers
  unreachable until git gc prunes it and silently reverts the cache to full redaction.
  The prefix is a plain file in the cache dir now.
• The redaction test suite was most of the checkpoint package's runtime. The 1MiB size
  gate forced every test to build and redact a megabyte of realistic content; 17 tests cost
  4m57s under -race and timed out CI at 10m. The gate is now test-overridable and the
  package runs in ~22s — faster than before this work started.

Re-measured 2026-08-23

Corpus: 95 .entire/logs/entire.log files, 57,619 lines, 1,465 paired
turn-end→shadow-commit spans and 287 perf spans. Both comparison windows below sit
after #1999, so the deleted entire-dev launcher is not a confound between them.

#2002 worked, and the ~3s floor is gone

Unbiased population metric (every turn, not just slow ones), non-CLI repos:

window	n	p50	p90
post-#1999, pre-#2002 (08-17..08-20)	58	2326ms	2747ms
post-#2002 (08-21+)	15	1103ms	1348ms

Against the original 3251ms p50 across 1,379 pre-fix spans, that closes item 1.

The composition of slow traces is the stronger evidence, because it names steps rather than
moving an aggregate:

dominant step	pre-#2002 (n=235)	post-#2002 (n=28)
push_checkpoint_refs	44.0% (n=60)	69.7% (n=15)
process_sessions	37.3% (n=74)	29.6% (n=12)
write_temporary_checkpoint	12.3% (n=51)	absent
redact_transcript	5.1% (n=27)	absent

The two redaction-path steps accounted for 78 of 235 slow traces and vanished entirely.

Do not read the slow-trace p50 as a regression

It rose 2592ms → 4063ms, and that is a selection effect, not a slowdown. The 1.5s
threshold is fixed, so removing a cluster of just-over-threshold traces raises the p50 of
what remains: the 1.5–3s band collapsed from 137 traces to 11, leaving the sample
dominated by genuinely slow network pushes. The unbiased metric above is the one that
answers "did it get faster".

What this reordered

process_sessions (item 2) became the top actionable cost — the only remaining non-network
item at 29.6% of slow-trace time. push_checkpoint_refs is larger at 69.7% but is network
I/O to the remote, so it may be inherent rather than a defect; it has never been examined
and is now the biggest single line item. The double compact-transcript generation (item 2b)
and the un-instrumented sentinel (item 3) both come out of this data.

Caveats

n is small post-fix (28 slow traces, 15 paired spans); the split assumes the local binary
picked up #2002 with the 08-21 nightly; and day-to-day workload varies enough to move these
numbers on its own (08-05..08-07 ran at a 9.4–11.2s p50). The step-name disappearances are
much stronger evidence than any of the aggregates.

Re-measuring

Slow root perf spans log at WARN since #1984, so this no longer needs a bespoke harness.
Aggregation shipped in #2092, so re-measuring is now one command:

entire doctor trace --summary --slow --last 500

It prints per-hook N / slow / p50 / p90 / max plus the step that dominates each hook, and
--json emits raw entries for scripting. Two things to know when comparing against numbers
taken before #2092:

• It reads one repo's log. doctor trace resolves .entire/logs/entire.log from the
  current worktree, so a cross-repo sweep still needs a grep -rh '"slow":true' over several
  checkouts. Run the command per repo rather than assuming it aggregates them.
• Dominance is time-weighted, not counted. The ad-hoc one-liner this replaces ranked
  steps by how often each was a trace's largest, which ties a 3900ms offender with a 150ms
  one and then resolves alphabetically — it can name the wrong step outright. Any ranking
  produced by counting should be re-derived, not carried forward.

Two traps, both of which produced wrong answers during the original investigation:

• Don't benchmark in this repo. Obsolete since refactor(hooks)!: remove local_dev mode #1999 (2026-08-17), which removed
  local_dev mode and deleted scripts/entire-dev. Hooks here now exec the plain entire
  binary from PATH, so timings taken in this repo are ordinary product timings. This trap was
  real while it lasted — the launcher go build/go run'd the CLI on every invocation
  (~1.53s warm), a cost no user paid, and it silently dominated any measurement. It is kept
  here only so old numbers can be read correctly: anything measured in this repo before
  2026-08-17 is inflated by it.
• git clone does not copy refs/entire/*. A clone has no checkpoint history, so it
  cannot reproduce costs that scale with accumulated sessions. Copy the repo instead.

Also: a sequential A/B lets page-cache warming leak across the boundary — it showed a fake
49% win for the object cache in #1985, which was 2% when interleaved.

_{Unrelated loose end from the same investigation, worked around in #2006 and worth
reporting upstream. Corrected 2026-08-23 — an earlier version of this paragraph named
muesli/cancelreader, which is the wrong target: Charm has re-implemented it inside
charmbracelet/ultraviolet, and the defect came across verbatim at poll_linux.go:123
and poll_bsd.go:113 (ultraviolet@v0.0.0-20260811164956), which is the code we
actually run. Both read r.file.Fd() after the blocking wake returns, racing a
caller's concurrent Close(); the fds are already known at construction, so caching
them as ints removes the race with no API or behaviour change. muesli/cancelreader
carries the same lines but is effectively unmaintained (last substantive merge
2022-06-22; 7 open PRs spanning 2022-2026, none merged), so a PR there would not land.
Separately, bubbletea's shutdown(kill=true) skips waitForReadLoop() and exposes no
API to await the reader, so a caller has no safe moment to reclaim a *os.File it
passed in — that one is a semantics question for the maintainers, not a drive-by
patch.}

[sdshah09]

I'd like to take a slice of this (not the whole issue). Prefer starting with one of:

• Item 3 — remove/shorten the dead waitForTranscriptFlush path (~520ms/Stop floor), using the suggested settle-on-stability shape (stable size across two polls + last line parses as complete JSON)
• Item 4 — extend perf: stop re-redacting whole transcripts on every checkpoint #2002 prefix reuse to condensation + Stop finalize so those paths don't still full-redact

Happy to take whichever you prefer first. I'll leave item 1 (unexplained ~3s p50) for after re-measurement with entire doctor trace --summary --slow outside this repo, and treat item 2 (process_sessions) as a follow-up.

Mind assigning me @Soph once the preferred slice is clear?

[Soph]

Sorry for the silence — you asked a direct question and I left it hanging for over a week.

Straight answer: both slices you offered are gone, and one of them is on me.

Item 4 I took myself in #2107 (merged 08-24) without claiming it here first. That's the coordination failure — you'd asked for it two days earlier and I should have either handed it over or said I was starting.

Item 3 is in #2099 (MuskanPaliwal), opened about two hours after your comment. Worth reading even though it isn't yours: it evaluates the exact shape you proposed — stable size across two polls plus a last line that parses as complete JSON — and rejects it, because a complete older prefix parses fine while the current turn hasn't reached the file yet. It then found something underneath the latency problem that my item-3 write-up missed: TranscriptPreparer returns only an error, so a successful wait proves path state A looked ready while lifecycle copies state B and finalization opens state C. Shortening the wait, which is what my framing invited, would have cut the 520ms and left that race in place.

Item 1 is answered, which closes the thing you deferred. Re-measured 08-23: population p50 2326ms → 1103ms across the #2002 boundary, with write_temporary_checkpoint and redact_transcript gone from slow traces entirely. Also drop the "outside this repo" caveat — #1999 deleted scripts/entire-dev, so hook timings measured in this repo are ordinary product timings now. Corrected in the issue.

What's actually open, if you still want a slice:

Item 2 — process_sessions. Now the top actionable cost: 29.6% of slow-trace time post-#2002, and the only remaining non-network item (push_checkpoint_refs is bigger at 69.7%, but that's remote I/O). docs/architecture/commit-hook-perf-analysis.md already lists concrete fixes — batch condensation into one commit, prune stale ENDED sessions, skip the orphan check for sessions with LastCheckpointID. Nothing has been done.

Item 2b — the compact transcript is generated twice per Stop. writeCompactTranscript has two call sites, checkpoint/persistent.go:1092 and :2069, and compact.FullWithBoundary compacts the whole session each time. Measured at 457ms + 447ms = 904ms of a 2505ms Stop, the largest single item in a Stop now that redaction is fixed. Same shape as what #2107 fixed, possibly the same remedy.

2b is the smaller and better-defined one if you want something self-contained. Say which and it's yours — I'll assign it this time.

[MuskanPaliwal]

One heads-up: #2131 already covers part of item 2.

It adds BatchSessions and shared batching code for both persistent layouts. A batch loads the checkpoint once, writes multiple sessions, rebuilds the summary once, creates one commit, and updates the ref once.

What remains is wiring PostCommit and process_sessions to group sessions and call BatchSessions. So item 2 is still open, but the storage half is already in #2131. If @sdshah09 takes it, we should coordinate around that PR to avoid doing the same work twice.

#2131 does not touch item 2b. That is still separate.