From ccc4a60d372542e2bbf335b7744c9ed6ab5301f2 Mon Sep 17 00:00:00 2001 From: ylm Date: Wed, 16 Sep 2026 17:56:26 -0400 Subject: [PATCH 1/2] Add per-write stage timing (realm:write-timing) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A card write holds the realm-wide write lock and reads the card back out of the index, but had no stage breakdown at all — so a slow write could not be attributed to the lock wait, the file write, the synchronous index, or the readback. Add a `realm:write-timing` log line, the write-path twin of `realm:search-timing`: each POST/PATCH handler stamps its sequential stages (POST: drain / serialize / write / readback; PATCH additionally lockWait / prepare) on a RequestTimings and emits one line keyed by the request's `x-boxel-logging-correlation-id`, so it joins to the same client-side timing and `realm:requests` line the search timing keys on. Emitted only when the write carries a correlation id — which the host's client-telemetry middleware already stamps on every write — so an uninstrumented write logs nothing. Co-Authored-By: Claude Opus 4.8 (1M context) Claude-Session: https://claude.ai/code/session_014GsYGsuCqHJz9GAti4jheG --- .../realm-server/tests/card-endpoints-test.ts | 118 ++++++++++++++++++ packages/runtime-common/index.ts | 1 + packages/runtime-common/realm.ts | 78 ++++++++++++ packages/runtime-common/write-timings.ts | 36 ++++++ 4 files changed, 233 insertions(+) create mode 100644 packages/runtime-common/write-timings.ts diff --git a/packages/realm-server/tests/card-endpoints-test.ts b/packages/realm-server/tests/card-endpoints-test.ts index 1bb23114f7e..5b19b2a4686 100644 --- a/packages/realm-server/tests/card-endpoints-test.ts +++ b/packages/realm-server/tests/card-endpoints-test.ts @@ -20,6 +20,8 @@ import { baseRRI, rri, searchEntryWireQueryFromQuery, + setWriteTimingSinkForTests, + X_BOXEL_LOGGING_CORRELATION_ID_HEADER, type LooseSingleCardDocument, type SingleCardDocument, } from '@cardstack/runtime-common'; @@ -1889,6 +1891,122 @@ module(basename(import.meta.filename), function () { ); }); + test('a write carrying a correlation id emits one realm:write-timing line per write, with a stage breakdown', async function (assert) { + let lines: string[] = []; + setWriteTimingSinkForTests((line) => lines.push(line)); + try { + let corr = 'test-write-corr-1'; + + let create = await request + .post('/') + .set(X_BOXEL_LOGGING_CORRELATION_ID_HEADER, corr) + .send({ + data: { + type: 'card', + attributes: { firstName: 'Timed' }, + meta: { + adoptsFrom: { module: rri('./friend.gts'), name: 'Friend' }, + }, + }, + } as LooseSingleCardDocument) + .set('Accept', 'application/vnd.card+json'); + assert.strictEqual(create.status, 201, `HTTP 201: ${create.text}`); + + let cardPath = (create.body as SingleCardDocument).data.id!.slice( + testRealmHref.length, + ); + let patch = await request + .patch(`/${cardPath}`) + .set(X_BOXEL_LOGGING_CORRELATION_ID_HEADER, corr) + .send({ + data: { + type: 'card', + attributes: { firstName: 'Retimed' }, + meta: { + adoptsFrom: { module: rri('./friend.gts'), name: 'Friend' }, + }, + }, + } as LooseSingleCardDocument) + .set('Accept', 'application/vnd.card+json'); + assert.strictEqual(patch.status, 200, `HTTP 200: ${patch.text}`); + + let postLine = lines.find( + (l) => l.includes(`corr=${corr}`) && l.includes('op=POST'), + ); + assert.ok( + postLine, + `a POST write-timing line was emitted (lines: ${JSON.stringify( + lines, + )})`, + ); + assert.ok( + /\btotal=\d+ms\b/.test(postLine!), + `the POST line carries a total (${postLine})`, + ); + assert.ok( + /\bwrite=\d+\b/.test(postLine!), + `the POST line carries the write stage (${postLine})`, + ); + assert.ok( + /\breadback=\d+\b/.test(postLine!), + `the POST line carries the readback stage (${postLine})`, + ); + + let patchLine = lines.find( + (l) => l.includes(`corr=${corr}`) && l.includes('op=PATCH'), + ); + assert.ok( + patchLine, + `a PATCH write-timing line was emitted (lines: ${JSON.stringify( + lines, + )})`, + ); + assert.ok( + /\blockWait=\d+\b/.test(patchLine!), + `the PATCH line carries the lockWait stage (${patchLine})`, + ); + assert.ok( + /\breadback=\d+\b/.test(patchLine!), + `the PATCH line carries the readback stage (${patchLine})`, + ); + } finally { + setWriteTimingSinkForTests(undefined); + } + }); + + test('a write without a correlation id emits no realm:write-timing line', async function (assert) { + let lines: string[] = []; + setWriteTimingSinkForTests((line) => lines.push(line)); + try { + let response = await request + .post('/') + .send({ + data: { + type: 'card', + attributes: { firstName: 'Untimed' }, + meta: { + adoptsFrom: { module: rri('./friend.gts'), name: 'Friend' }, + }, + }, + } as LooseSingleCardDocument) + .set('Accept', 'application/vnd.card+json'); + assert.strictEqual( + response.status, + 201, + `HTTP 201: ${response.text}`, + ); + assert.strictEqual( + lines.length, + 0, + `no write-timing line without a correlation id (lines: ${JSON.stringify( + lines, + )})`, + ); + } finally { + setWriteTimingSinkForTests(undefined); + } + }); + test('an echoed serve-time meta.screenshots never persists into the source file', async function (assert) { // The shape a card+json GET stamps — a client that GETs a doc and // POSTs it back to duplicate the card echoes this, and persisting diff --git a/packages/runtime-common/index.ts b/packages/runtime-common/index.ts index 35928d28e0b..132f55e4812 100644 --- a/packages/runtime-common/index.ts +++ b/packages/runtime-common/index.ts @@ -1688,6 +1688,7 @@ export * from './search-bounds.ts'; export * from './ttl-response-cache.ts'; export * from './card-document-cache.ts'; export * from './request-timings.ts'; +export * from './write-timings.ts'; export * from './prerendered-html-format.ts'; export * from './query-field-utils.ts'; export * from './relationship-utils.ts'; diff --git a/packages/runtime-common/realm.ts b/packages/runtime-common/realm.ts index afed3b37866..52f787caeec 100644 --- a/packages/runtime-common/realm.ts +++ b/packages/runtime-common/realm.ts @@ -262,6 +262,8 @@ import { sanitizeLoggingCorrelationId, X_BOXEL_LOGGING_CORRELATION_ID_HEADER, } from './prerender-headers.ts'; +import { RequestTimings } from './request-timings.ts'; +import { emitWriteTiming } from './write-timings.ts'; import { mergeRelationships } from './merge-relationships.ts'; import { getCardDirectoryName } from './helpers/card-directory-name.ts'; import { @@ -7604,6 +7606,30 @@ export class Realm { // (the pre-write drain, and reading the card back out of the index vs. // echoing it) and nothing prerender-specific beyond them. let answerFromEcho = duringPrerender || isSkipIndexWaitRequest(request); + // Per-write stage timing, emitted as one `realm:write-timing` line when the + // request carries a correlation id (see write-timings.ts). `mark(stage)` + // stamps the wall-clock elapsed since the previous mark; `emit(outcome)` + // renders the line. Both are no-ops for an uninstrumented write. + let handlerStart = Date.now(); + let correlationId = sanitizeLoggingCorrelationId( + request.headers.get(X_BOXEL_LOGGING_CORRELATION_ID_HEADER), + ); + let timings = correlationId ? new RequestTimings() : undefined; + let lastMark = handlerStart; + let mark = (stage: string) => { + let now = Date.now(); + timings?.add(stage, now - lastMark); + lastMark = now; + }; + let emit = (outcome: string) => { + if (timings && correlationId) { + emitWriteTiming( + `corr=${correlationId} op=POST outcome=${outcome} total=${ + Date.now() - handlerStart + }ms ${timings.toLogFragment()}`, + ); + } + }; // Drain any in-flight incremental indexing before serializing the new // card, so the JSON-API path tolerates an immediately-preceding deferred // +source POST without disturbing the +json POST's own @@ -7631,6 +7657,7 @@ export class Realm { await pending; } } + mark('drain'); let body = await request.text(); let json; try { @@ -7726,11 +7753,16 @@ export class Realm { lid: primaryResource.lid, }); } + mark('serialize'); let [{ lastModified, created }] = await this.writeMany(files, { clientRequestId: request.headers.get('X-Boxel-Client-Request-Id'), initiatingUser: requestContext.authenticatedUser ?? null, ...(answerFromEcho ? { waitForIndex: false } : {}), }); + // On the default path `writeMany` also awaits the card's synchronous + // index; the echo path passes `waitForIndex: false`, so this stage is the + // durable file write alone. + mark('write'); let newURL = primaryResourceURL.href.replace(/\.json$/, ''); let doc: SingleCardDocument; @@ -7742,6 +7774,8 @@ export class Realm { newURL, lastModified, ); + mark('echo'); + emit('echo'); } else { // The write response is read only for the primary card's assigned id // and realm-info; the client discards its attributes, relationships and @@ -7770,6 +7804,8 @@ export class Realm { meta: { lastModified }, }, }); + mark('readback'); + emit('indexed'); } this.#serveInstanceIdsAsRRI(doc); return createResponse({ @@ -7809,6 +7845,32 @@ export class Realm { // serialized echo rather than a readback. let answerFromEcho = duringPrerender || isSkipIndexWaitRequest(request); + // Per-write stage timing, emitted as one `realm:write-timing` line when the + // request carries a correlation id (see write-timings.ts). Unlike the POST + // path, a PATCH also waits on the realm-wide write lock — `lockWait` is + // stamped when the critical section opens, so contention is attributable. + // `mark`/`emit` are no-ops for an uninstrumented write. + let handlerStart = Date.now(); + let correlationId = sanitizeLoggingCorrelationId( + request.headers.get(X_BOXEL_LOGGING_CORRELATION_ID_HEADER), + ); + let timings = correlationId ? new RequestTimings() : undefined; + let lastMark = handlerStart; + let mark = (stage: string) => { + let now = Date.now(); + timings?.add(stage, now - lastMark); + lastMark = now; + }; + let emit = (outcome: string) => { + if (timings && correlationId) { + emitWriteTiming( + `corr=${correlationId} op=PATCH outcome=${outcome} total=${ + Date.now() - handlerStart + }ms ${timings.toLogFragment()}`, + ); + } + }; + let { data: patch, included: maybeIncluded } = await request.json(); if (!isCardResource(patch)) { return badRequest({ @@ -7843,6 +7905,9 @@ export class Realm { // public `writeMany` — re-entering the lock through the public method // would block on a different pinned pool connection. return await this.#dbAdapter.withWriteLock(this.url, async () => { + // Time from the handler start (before validation) to the lock opening. + // Under contention this is the term that dominates a slow PATCH. + mark('lockWait'); let primarySerialization: LooseSingleCardDocument | undefined; // The merge base is the stored source file, not the index. The // index is downstream of the file and can lag it — a backlogged or @@ -7944,6 +8009,9 @@ export class Realm { } } + // The existing-file read plus the merge above are the prepare stage; + // the write and readback below are timed separately. + mark('prepare'); // If the patch makes no semantic changes and doesn't include side-loaded // resources, short-circuit to avoid touching the file (and changing mtime). if (included.length === 0 && isEqual(primaryResource, original)) { @@ -7954,6 +8022,7 @@ export class Realm { let entry = await this.#realmIndexQueryEngine.cardDocument( new URL(instanceURL), ); + mark('readback'); if (entry && entry.type !== 'error') { let existingDoc = merge({}, entry.doc, { data: { @@ -7983,6 +8052,7 @@ export class Realm { // conditional GET 304 onto this closure-less body. The client // discards the echo body anyway, so it has no validator to gain. this.#serveInstanceIdsAsRRI(existingDoc); + emit('noop'); return createResponse({ body: JSON.stringify(existingDoc, null, 2), init: { @@ -8060,6 +8130,7 @@ export class Realm { primarySerialization = fileSerialization; } } + mark('serialize'); // Use the unlocked inner write so we don't re-enter // withWriteLock (which would block on a different pinned pool // connection). @@ -8068,6 +8139,9 @@ export class Realm { initiatingUser: requestContext.authenticatedUser ?? null, ...(answerFromEcho ? { waitForIndex: false } : {}), }); + // On the default path `_batchWriteUnlocked` also awaits the card's + // synchronous index; the echo path passes `waitForIndex: false`. + mark('write'); let doc: SingleCardDocument; if (answerFromEcho) { // See serializedInstanceEcho: the write indexed deferred, so there is @@ -8078,6 +8152,8 @@ export class Realm { lastModified, ); this.#serveInstanceIdsAsRRI(doc); + mark('echo'); + emit('echo'); return createResponse({ body: JSON.stringify(doc, null, 2), init: { @@ -8103,6 +8179,7 @@ export class Realm { let entry = await this.#realmIndexQueryEngine.cardDocument( new URL(instanceURL), ); + mark('readback'); if (!entry || entry?.type === 'error') { if ( primarySerialization && @@ -8156,6 +8233,7 @@ export class Realm { // emitting one would let a conditional GET 304 onto this closure-less // body. The client discards the echo body anyway. this.#serveInstanceIdsAsRRI(doc); + emit('indexed'); return createResponse({ body: JSON.stringify(doc, null, 2), init: { diff --git a/packages/runtime-common/write-timings.ts b/packages/runtime-common/write-timings.ts new file mode 100644 index 00000000000..5abdb057c27 --- /dev/null +++ b/packages/runtime-common/write-timings.ts @@ -0,0 +1,36 @@ +import { logger } from './log.ts'; + +// One `realm:write-timing` line per instrumented card write (POST create / +// PATCH update), the write-path twin of `realm:search-timing`. A card write +// holds the realm-wide write lock and reads the card back out of the index, +// but until now had no stage breakdown at all — so a slow write could not be +// attributed to the lock wait, the file write, the index wait, or the +// readback. Each handler stamps its sequential stages on a `RequestTimings` +// and emits one line here, keyed by the request's `x-boxel-logging-correlation-id` +// so it joins to the same client-side timing (and the `realm:requests` line) +// the search timing already keys on. +// +// Emitted only when the write carries a correlation id, exactly like +// `emitSearchTiming` — an uninstrumented write logs nothing. + +// Indirection so a test can deterministically capture the emitted line, for +// the same reason `emitSearchTiming` has one: loglevel rebinds a logger's +// methods on every `setLevel`, so a test that monkeypatches a direct logger +// handle would race the next `logger('realm:write-timing')` call. A settable +// sink sidesteps that. Defaults to the `realm:write-timing` logger. +let writeTimingSink: ((line: string) => void) | undefined; +let writeTimingLog: ReturnType | undefined; +export function setWriteTimingSinkForTests( + sink: ((line: string) => void) | undefined, +): void { + writeTimingSink = sink; +} +export function emitWriteTiming(line: string): void { + if (writeTimingSink) { + writeTimingSink(line); + return; + } + // Lazy: a module-load `logger()` call races the circular import that + // installs the logger factory. First emission happens well after boot. + (writeTimingLog ??= logger('realm:write-timing')).info(line); +} From 369afd31edbe2b32a5c97ec4a4c00f93811023a6 Mon Sep 17 00:00:00 2001 From: ylm Date: Wed, 16 Sep 2026 18:41:45 -0400 Subject: [PATCH 2/2] Address write-timing review: POST lockWait, error outcomes, no-op double-count - POST now takes the write lock explicitly (via withWriteLock + _batchWriteUnlocked, which is exactly what writeMany does) so the lock wait is its own `lockWait` stage, matching the PATCH path. Previously a POST's lock contention folded into `write`, leaving it as invisible as before the instrumentation. - 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. - The no-op PATCH short-circuit marks `readback` inside its success guard, so the rare fall-through (a no-op patch against an errored index row) doesn't double-count `readback` (RequestTimings.add sums repeated keys). - Reword the write-timings.ts header comment off the temporal "until now". - Assert the POST timing line now carries `lockWait`. Co-Authored-By: Claude Opus 4.8 (1M context) Claude-Session: https://claude.ai/code/session_014GsYGsuCqHJz9GAti4jheG --- .../realm-server/tests/card-endpoints-test.ts | 4 ++ packages/runtime-common/realm.ts | 38 ++++++++++++++----- packages/runtime-common/write-timings.ts | 2 +- 3 files changed, 34 insertions(+), 10 deletions(-) diff --git a/packages/realm-server/tests/card-endpoints-test.ts b/packages/realm-server/tests/card-endpoints-test.ts index 5b19b2a4686..7f0df166511 100644 --- a/packages/realm-server/tests/card-endpoints-test.ts +++ b/packages/realm-server/tests/card-endpoints-test.ts @@ -1943,6 +1943,10 @@ module(basename(import.meta.filename), function () { /\btotal=\d+ms\b/.test(postLine!), `the POST line carries a total (${postLine})`, ); + assert.ok( + /\blockWait=\d+\b/.test(postLine!), + `the POST line carries the lockWait stage (${postLine})`, + ); assert.ok( /\bwrite=\d+\b/.test(postLine!), `the POST line carries the write stage (${postLine})`, diff --git a/packages/runtime-common/realm.ts b/packages/runtime-common/realm.ts index 52f787caeec..4716061a4aa 100644 --- a/packages/runtime-common/realm.ts +++ b/packages/runtime-common/realm.ts @@ -7754,14 +7754,27 @@ export class Realm { }); } mark('serialize'); - let [{ lastModified, created }] = await this.writeMany(files, { - clientRequestId: request.headers.get('X-Boxel-Client-Request-Id'), - initiatingUser: requestContext.authenticatedUser ?? null, - ...(answerFromEcho ? { waitForIndex: false } : {}), - }); - // On the default path `writeMany` also awaits the card's synchronous - // index; the echo path passes `waitForIndex: false`, so this stage is the - // durable file write alone. + // Take the write lock explicitly (rather than through `writeMany`, which + // is exactly `withWriteLock(() => _batchWriteUnlocked(...))`) so the wait + // for it is its own `lockWait` stage, as on the PATCH path. `writeMany` + // folds the lock acquisition into the write, and under contention that + // wait — not the file write or index — is what dominates; leaving it + // inside `write` would make a POST's lock contention as invisible as it + // was before this instrumentation. + let [{ lastModified, created }] = await this.#dbAdapter.withWriteLock( + this.url, + async () => { + mark('lockWait'); + return this._batchWriteUnlocked(files, { + clientRequestId: request.headers.get('X-Boxel-Client-Request-Id'), + initiatingUser: requestContext.authenticatedUser ?? null, + ...(answerFromEcho ? { waitForIndex: false } : {}), + }); + }, + ); + // On the default path `_batchWriteUnlocked` also awaits the card's + // synchronous index; the echo path passes `waitForIndex: false`, so this + // stage is the durable file write alone. mark('write'); let newURL = primaryResourceURL.href.replace(/\.json$/, ''); @@ -7791,6 +7804,8 @@ export class Realm { let err = entry ? CardError.fromSerializableError(entry.error) : undefined; + mark('readback'); + emit('error'); return systemError({ requestContext, message: `Unable to index newly created card: ${newURL}, can't find new instance in index`, @@ -8022,8 +8037,12 @@ export class Realm { let entry = await this.#realmIndexQueryEngine.cardDocument( new URL(instanceURL), ); - mark('readback'); + // Marked inside the guard, not before it: on the rare fall-through + // (a no-op patch against an errored index row) the normal write path + // below marks its own `readback`, and `RequestTimings.add` sums + // repeated keys — so an unconditional mark here would double-count. if (entry && entry.type !== 'error') { + mark('readback'); let existingDoc = merge({}, entry.doc, { data: { links: { self: instanceURL }, @@ -8197,6 +8216,7 @@ export class Realm { }, }) as SingleCardDocument; } else { + emit('error'); return systemError({ requestContext, message: `Unable to index card: can't find patched instance, ${instanceURL} in index`, diff --git a/packages/runtime-common/write-timings.ts b/packages/runtime-common/write-timings.ts index 5abdb057c27..65ac1e77ff3 100644 --- a/packages/runtime-common/write-timings.ts +++ b/packages/runtime-common/write-timings.ts @@ -3,7 +3,7 @@ import { logger } from './log.ts'; // One `realm:write-timing` line per instrumented card write (POST create / // PATCH update), the write-path twin of `realm:search-timing`. A card write // holds the realm-wide write lock and reads the card back out of the index, -// but until now had no stage breakdown at all — so a slow write could not be +// with no other stage breakdown — so a slow write cannot otherwise be // attributed to the lock wait, the file write, the index wait, or the // readback. Each handler stamps its sequential stages on a `RequestTimings` // and emits one line here, keyed by the request's `x-boxel-logging-correlation-id`