Skip to content

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

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
lukemelia wants to merge 2 commits into from
+262 −5
Closed

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

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
ccc4a60
Add per-write stage timing (realm:write-timing)
Sep 16, 2026
369afd3
Address write-timing review: POST lockWait, error outcomes, no-op dou…
Sep 16, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
122 changes: 122 additions & 0 deletions packages/realm-server/tests/card-endpoints-test.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,8 @@ import {
baseRRI,
rri,
searchEntryWireQueryFromQuery,
setWriteTimingSinkForTests,
X_BOXEL_LOGGING_CORRELATION_ID_HEADER,
type LooseSingleCardDocument,
type SingleCardDocument,
} from '@cardstack/runtime-common';
Expand Down Expand Up @@ -1889,6 +1891,126 @@ 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(
/\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})`,
);
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
Expand Down
1 change: 1 addition & 0 deletions packages/runtime-common/index.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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';
Expand Down
108 changes: 103 additions & 5 deletions packages/runtime-common/realm.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down Expand Up @@ -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()}`,
);
}
};
Comment on lines +7624 to +7632

@habdelra habdelra Sep 16, 2026

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

[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

// 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
Expand Down Expand Up @@ -7631,6 +7657,7 @@ export class Realm {
await pending;
}
}
mark('drain');
let body = await request.text();
let json;
try {
Expand Down Expand Up @@ -7726,11 +7753,29 @@ export class Realm {
lid: primaryResource.lid,
});
}
let [{ lastModified, created }] = await this.writeMany(files, {
clientRequestId: request.headers.get('X-Boxel-Client-Request-Id'),
initiatingUser: requestContext.authenticatedUser ?? null,
...(answerFromEcho ? { waitForIndex: false } : {}),
});
mark('serialize');
// 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$/, '');
let doc: SingleCardDocument;
Expand All @@ -7742,6 +7787,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
Expand All @@ -7757,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`,
Expand All @@ -7770,6 +7819,8 @@ export class Realm {
meta: { lastModified },
},
});
mark('readback');
emit('indexed');
}
this.#serveInstanceIdsAsRRI(doc);
return createResponse({
Expand Down Expand Up @@ -7809,6 +7860,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()}`,
);
}
};
Comment on lines +7868 to +7887

@habdelra habdelra Sep 16, 2026

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

[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


let { data: patch, included: maybeIncluded } = await request.json();
if (!isCardResource(patch)) {
return badRequest({
Expand Down Expand Up @@ -7843,6 +7920,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');
Comment on lines +7923 to +7925

@habdelra habdelra Sep 16, 2026

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

[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

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
Expand Down Expand Up @@ -7944,6 +8024,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)) {
Expand All @@ -7954,7 +8037,12 @@ export class Realm {
let entry = await this.#realmIndexQueryEngine.cardDocument(
new URL(instanceURL),
);
// 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 },
Expand Down Expand Up @@ -7983,6 +8071,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: {
Expand Down Expand Up @@ -8060,6 +8149,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).
Expand All @@ -8068,6 +8158,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
Expand All @@ -8078,6 +8171,8 @@ export class Realm {
lastModified,
);
this.#serveInstanceIdsAsRRI(doc);
mark('echo');
emit('echo');
return createResponse({
body: JSON.stringify(doc, null, 2),
init: {
Expand All @@ -8103,6 +8198,7 @@ export class Realm {
let entry = await this.#realmIndexQueryEngine.cardDocument(
new URL(instanceURL),
);
mark('readback');
if (!entry || entry?.type === 'error') {
if (
primarySerialization &&
Expand All @@ -8120,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`,
Expand Down Expand Up @@ -8156,6 +8253,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: {
Expand Down
Loading
Loading