Add per-write stage timing (realm:write-timing)

[lukemelia]

Stacked on #6162 — review/merge that first. This PR's diff against its base is the second commit only.

Why

A card write holds the realm-wide write lock and reads the card back out of the index, but has no stage breakdown at all — so a slow write can't be attributed to the lock wait, the file write, the synchronous index, or the readback. In production one PATCH took 192s with only 14s of index time; the other ~178s is currently unattributable. #6162 removes one known cost (the readback closure) but without instrumentation the win isn't measurable and the remaining tail stays invisible.

What

Adds realm:write-timing, the write-path twin of realm:search-timing. Each POST/PATCH handler stamps its sequential stages on a RequestTimings and emits one line, keyed by the request's x-boxel-logging-correlation-id:

• POST: drain / serialize / write / readback (or echo)
• PATCH: lockWait / prepare / serialize / write / readback (or echo, or noop for the no-op short-circuit)

lockWait (time from handler entry to the write lock opening) is the term that dominates a slow PATCH under contention — previously invisible. Each line also carries op=, outcome=, and total=<wall-clock>ms.

Emitted only when the write carries a correlation id — which the host's client-telemetry middleware already stamps on every non-Matrix request, writes included (client-telemetry.ts) — so it joins to the same client-side timing and realm:requests line the search timing already keys on. An uninstrumented write logs nothing.

Reuses the existing RequestTimings collector and mirrors emitSearchTiming's test-sink indirection (setWriteTimingSinkForTests) so the emitted line can be captured deterministically.

Test

Adds two realm-server tests: a POST+PATCH carrying a correlation id emits one op=POST and one op=PATCH line with the expected stage keys (write/readback, lockWait/readback); a write without a correlation id emits nothing.

Verification status

• Typecheck (runtime-common + realm-server): clean
• ESLint: clean
• Realm-server suite not executed locally (needs the dev stack rebuilt against this checkout); CI will run it.

🤖 Generated with Claude Code

[lukemelia]

[Claude Code 🤖] Reviewed the instrumentation for stage-attribution accuracy — whether each write path emits exactly once and whether each stage measures what its name claims — plus the reuse of RequestTimings / the emitSearchTiming test-sink twin, and whether the two tests fail without the code and resist contamination.

No blocking issues. emitWriteTiming mirrors emitSearchTiming faithfully, the channel emits at the default *=info level exactly like search timing, and both tests are sound: they fail without the instrumentation, filter by a unique corr, and the server never mints a correlation id (middleware only echoes an inbound one), so the negative test holds.

1. POST lock contention stays invisible — POST's write stage folds in the realm write-lock acquisition, the one term this feature exists to surface. See the inline thread on the POST mark('write').
2. Slow writes that error emit nothing. Every systemError return — including the ones after write / readback, inside the lock — bypasses emit, so the slowest failures (arguably the ones most worth attributing) produce no line. Consider an emit('error') before those returns. Follow-up, non-blocking.
3. Minor readback double-count on one edge path — see the inline thread on the short-circuit mark('readback').

Adjacent, out of scope: the write-timings.ts header comment's “until now had no stage breakdown” is temporal/journey phrasing the evergreen convention avoids — “has no other stage breakdown” reads the same without dating the code.

[lukemelia]

[Claude Code 🤖] POST's write stage silently includes the realm write-lock acquisition, so POST lock contention — the very term this feature exists to surface — stays invisible on creates. writeMany wraps _batchWriteUnlocked in withWriteLock (see writeMany in this file), so on a POST that queues behind other writers the lock wait folds into write, indistinguishable from the file write and the index. PATCH breaks it out only because it opens its own withWriteLock and marks lockWait inside the callback — a POST under the same contention as the cited slow PATCH would be equally slow and equally unattributable.

The way out: mirror PATCH — take the lock explicitly in the POST handler (withWriteLock(this.url, async () => { mark('lockWait'); … _batchWriteUnlocked(files, …) … })) and mark lockWait when the callback opens. If that restructure is out of scope here, at minimum extend this comment to say write folds in the lock-acquisition wait, so the PATCH/POST asymmetry isn't read as “POST never waits on the lock.”

Class: follow-up (the feature still delivers for PATCH, the cited case). Non-blocking.

[lukemelia]

[Claude Code 🤖] Done in 369afd3 — POST now opens its own withWriteLock and marks lockWait inside it (calling _batchWriteUnlocked directly, which is exactly what writeMany wrapped, so behavior is unchanged), making POST lock contention its own stage like PATCH. Added a lockWait= assertion to the POST timing test.

[habdelra]

[Claude Code 🤖] Resolved. Verified the restructure is behavior-preserving: writeMany is literally this.#dbAdapter.withWriteLock(this.url, () => this._batchWriteUnlocked(files, options)), and the POST handler now inlines exactly that with mark('lockWait') as the first statement in the callback — so lockWait on a POST is the wait from mark('serialize') to the critical section opening, with nothing else folded in.

One follow-on the change creates: the writeMany doc comment enumerates the handlers that take the lock themselves as "those that need their READ inside the same critical section (the /_atomic precheck and patchCardInstance's existing-file read)". createCard is now a third direct _batchWriteUnlocked caller and its reason isn't that one — worth a clause there so the next person auditing lock usage doesn't read an undocumented caller as a mistake.

---

Generated by Claude Code

[lukemelia]

[Claude Code 🤖] Minor: readback is double-counted on one edge path. When the no-op short-circuit condition matches but the index row is an error, this block doesn't return — it falls through to the normal write path, which marks readback again. RequestTimings.add sums repeated keys, so that one line reports readback as both reads (plus a stray prepare). Rare (a no-op patch against an errored row) and the line still emits with outcome=indexed, so it's cosmetic — move this mark under the entry && entry.type !== 'error' guard, or give it a distinct stage name. Non-blocking.

[lukemelia]

[Claude Code 🤖] Done in 369afd3 — the short-circuit mark('readback') moved inside the entry && entry.type !== 'error' guard, so the fall-through (a no-op patch against an errored row) no longer double-counts.

[habdelra]

[Claude Code 🤖] Resolved — the double-count is gone; the fall-through now reaches the normal path with readback unstamped.

Residual, cosmetic, no action needed unless it bothers you: on that same fall-through the short-circuit's cardDocument read is now attributed to serialize (it's the next mark), so that one line's serialize carries an index read. Still adds up to wall-clock, just mislabeled on a path that's already rare.

---

Generated by Claude Code

[lukemelia]

[Claude Code 🤖] Also addressed the two review-body items in 369afd3:

• Error outcomes — the two post-readback index-failure returns (POST create, PATCH update) now emit('error'), so a slow write that fails is attributed rather than logging nothing.
• Evergreen — the write-timings.ts header comment is reworded off the temporal "until now".

runtime-common typechecks clean; CI will run the realm-server suite (the new POST lockWait path and the moved no-op mark are exercised by the existing write-timing test).

[habdelra]

[Claude Code 🤖] Re-review of the follow-up commit: verified both earlier threads against the code (not the description), then went after what the emitted stages actually measure and which exits emit at all. Not covered: the base PR's echo/link-closure change, and the realm-server suite has not finished on this head.

Both earlier threads are resolved, and the POST restructure is behavior-preserving — writeMany is exactly withWriteLock(() => _batchWriteUnlocked(…)), verified in this file. No blocking issues; the one finding worth acting on before this ships is that PATCH's lockWait doesn't measure lock wait.

1. PATCH lockWait folds in the body read and validation, so it can't answer the question the PR is built to answer — one mark('parse') before the lock fixes it. See the thread on mark('lockWait'). (Regression, non-blocking.)
2. Non-happy exits emit nothing — a PATCH that pays the full lock wait and then 404s, and any throw, produce no line. A finally-emit covers all of them. (Follow-up.)
3. The mark/emit collector is duplicated verbatim across the two handlers and has already drifted within this diff; one factory in write-timings.ts also makes item 2 a single change. (Follow-up.)
4. The writeMany doc comment enumerates the handlers that take the lock directly and why; createCard is now a third one for a reason that rule doesn't cover. One clause. (Follow-up, outside the diff — see the POST thread.)

CI is still running on this head; nothing red so far, so nothing to act on there yet.

---

Generated by Claude Code

[habdelra]

[Claude Code 🤖] PATCH's lockWait is not lock wait — it is await request.json() (the body read off the socket) + the isCardResource / included validation + the lock acquisition, since handlerStart is stamped before request.json() and this is the first mark. The comment two lines up asserts contention dominates it, which is exactly the inference the stage can't support: on the 192s PATCH this feature exists to explain, a lockWait=178000 leaves lock contention and a stalled body read indistinguishable, and those have opposite remedies (admission control vs. client/proxy).

The POST path doesn't have this — its lockWait starts at mark('serialize'), immediately before the lock. Give PATCH the same shape: mark('parse') right after the included validation loop and before withWriteLock, so lockWait is the wait alone.

Class: regression (introduced here, and it's the stage the PR's own motivating case turns on). Non-blocking — the line is still strictly more than exists today — but worth the two lines before this ships as the thing people read lock contention off.

---

Generated by Claude Code

[habdelra]

[Claude Code 🤖] Every non-happy exit still logs nothing, including the slow ones. emit fires only from the explicit return sites, so nothing is emitted when: a POST bails at any of the five badRequest returns after mark('drain') (the drain can be the long stage); a PATCH returns notFound for a missing source file — after paying the full lock wait; or anything throws out of _batchWriteUnlocked, the readback, or the merge. A write that takes 190s and then throws is the case most worth attributing, and it's the one that produces no line at all.

A try { … } finally { if (!emitted) emit('throw') } around each handler body covers all three shapes at once, with emit setting the flag so a normal return still wins the outcome label.

Class: follow-up (the same gap exists in emitSearchTiming, so not introduced here). Non-blocking.

---

Generated by Claude Code

[habdelra]

[Claude Code 🤖] This 20-line collector is byte-identical to the POST one apart from op=PATCH, and the two are already drifting in this PR's own diff (POST marks lockWait adjacent to the lock, PATCH from handler entry — see the comment on mark('lockWait') below). A third write path picking this up copies it a third time.

Suggest one home in write-timings.ts:

export function writeTimer(request: Request, op: 'POST' | 'PATCH') {
  let start = Date.now();
  let corr = sanitizeLoggingCorrelationId(
    request.headers.get(X_BOXEL_LOGGING_CORRELATION_ID_HEADER),
  );
  let timings = corr ? new RequestTimings() : undefined;
  let last = start;
  return {
    mark(stage: string) { let now = Date.now(); timings?.add(stage, now - last); last = now; },
    emit(outcome: string) {
      if (!timings || !corr) return;
      emitWriteTiming(`corr=${corr} op=${op} outcome=${outcome} total=${Date.now() - start}ms ${timings.toLogFragment()}`);
    },
  };
}

It also makes the finally-emit in the other comment a one-place change rather than two.

Class: follow-up. Non-blocking.

---

Generated by Claude Code

[github-actions]

Host Test Results

    1 files      1 suites   2h 36m 37s ⏱️
4 653 tests 4 631 ✅ 12 💤  1 ❌ 9 🔥
4 668 runs  4 637 ✅ 12 💤 10 ❌ 9 🔥

Results for commit 369afd3.

For more details on these errors, see this check.

Realm Server Test Results

    1 files    235 suites   1h 20m 3s ⏱️
3 379 tests 3 376 ✅ 0 💤 3 ❌
3 426 runs  3 423 ✅ 0 💤 3 ❌

Results for commit 369afd3.

For more details on these errors, see this check.

[FadhlanR]

Closing this in favor of #6166, which now carries the whole of this ticket.