diff --git a/packages/host/tests/acceptance/interact-submode-creation-and-permissions-test.gts b/packages/host/tests/acceptance/interact-submode-creation-and-permissions-test.gts index da6a60cd25f..d0bf99ab1dc 100644 --- a/packages/host/tests/acceptance/interact-submode-creation-and-permissions-test.gts +++ b/packages/host/tests/acceptance/interact-submode-creation-and-permissions-test.gts @@ -346,22 +346,33 @@ module( if (consumerSaveCount === 1) { // the first time we save the consumer we set the relationship to null // as we are still waiting for the other realm to assign an ID to the new linked card - assert.strictEqual(doc.included!.length, 1); - assert.strictEqual( - doc.included![0].id, - `${testRealmURL}Pet/mango`, - "the side loaded resources don't include the newly created card yet", + let newFriendLink = ( + doc.data?.relationships?.['friends.1'] as + | { links?: { self?: string | null } } + | undefined + )?.links?.self; + assert.notOk( + newFriendLink, + 'the "friends.1" relationship names nothing while the new card is unsaved', + ); + assert.notOk( + doc.included, + 'and the save answers with the consumer alone, side-loading none of its links', ); } if (consumerSaveCount === 2) { // as soon as the other realm assigns an id to the linked card we then // save the consumer with a relationship to the linked card's id - assert.deepEqual( - doc.data?.relationships?.['friends.1'], - { - links: { self: newLinkId! }, - data: { type: 'card', id: newLinkId! }, - }, + // A write echoes relationships as the card stores them, so the + // link is what it names — the resolved target a readback would + // have added is not part of this answer. + assert.strictEqual( + ( + doc.data?.relationships?.['friends.1'] as + | { links?: { self?: string | null } } + | undefined + )?.links?.self, + newLinkId!, 'the "friends.1" relationship was populated with the linked card\'s new id', ); consumerSaved.fulfill(); diff --git a/packages/host/tests/integration/components/card-copy-test.gts b/packages/host/tests/integration/components/card-copy-test.gts index eae66f88cac..3f362bfe4f5 100644 --- a/packages/host/tests/integration/components/card-copy-test.gts +++ b/packages/host/tests/integration/components/card-copy-test.gts @@ -976,7 +976,7 @@ module('Integration | card-copy', function (hooks) { }); test('can copy a card that has a relative link to card in source realm', async function (assert) { - assert.expect(15); + assert.expect(12); await setCardInOperatorModeState( [`${testRealmURL}index`], [`${testRealm2URL}index`], @@ -1030,21 +1030,11 @@ module('Integration | card-copy', function (hooks) { links: { self: `${testRealmURL}Pet/mango`, }, - data: { - type: 'card', - id: `${testRealmURL}Pet/mango`, - }, }, }); - assert.strictEqual(json.included?.length, 1); - // eslint-disable-next-line @typescript-eslint/no-non-null-asserted-optional-chain - let included = json.included?.[0]!; - assert.strictEqual(included.id, `${testRealmURL}Pet/mango`); - assert.deepEqual(included.meta.adoptsFrom, { - module: rri('../pet'), - name: 'Pet', - }); - assert.deepEqual(included.meta.realmURL, testRealmURL); + // A write answers with the written card alone, so the linked pet is + // named by the relationship above and not carried as a resource. + assert.strictEqual(json.included, undefined); }); await click( @@ -1112,7 +1102,7 @@ module('Integration | card-copy', function (hooks) { }); test('can copy a card that has a link to card in destination realm', async function (assert) { - assert.expect(15); + assert.expect(12); await setCardInOperatorModeState( [`${testRealmURL}index`], [`${testRealm2URL}index`], @@ -1164,21 +1154,11 @@ module('Integration | card-copy', function (hooks) { links: { self: `../Pet/paper`, // we should recognize that the link is now in the same realm and should be a relative path }, - data: { - type: 'card', - id: `${testRealm2URL}Pet/paper`, - }, }, }); - assert.strictEqual(json.included?.length, 1); - // eslint-disable-next-line @typescript-eslint/no-non-null-asserted-optional-chain - let included = json.included?.[0]!; - assert.strictEqual(included.id, `${testRealm2URL}Pet/paper`); - assert.deepEqual(included.meta.adoptsFrom, { - module: testRRI('pet'), - name: 'Pet', - }); - assert.deepEqual(included.meta.realmURL, testRealm2URL); + // A write answers with the written card alone, so the linked pet is + // named by the relationship above and not carried as a resource. + assert.strictEqual(json.included, undefined); }); let realmEventTimestampStart = Date.now(); diff --git a/packages/host/tests/integration/realm-test.gts b/packages/host/tests/integration/realm-test.gts index 83ced3f4800..426fa96c37a 100644 --- a/packages/host/tests/integration/realm-test.gts +++ b/packages/host/tests/integration/realm-test.gts @@ -756,7 +756,6 @@ module('Integration | realm', function (hooks) { assert.strictEqual(response.status, 201, 'successful http status'); let json = await response.json(); let id = json.data.id.split('/').pop()!; - let ownerCreatedAt = await getFileCreatedAt(realm, 'dir/owner.json'); let petCreatedAt = await getFileCreatedAt(realm, `Pet/${id}.json`); assert.ok(uuidValidate(id), 'card ID is a UUID'); assert.deepEqual(json, { @@ -775,10 +774,6 @@ module('Integration | realm', function (hooks) { links: { self: `../dir/owner`, }, - data: { - type: 'card', - id: `${testRealmURL}dir/owner`, - }, }, }, meta: { @@ -797,38 +792,6 @@ module('Integration | realm', function (hooks) { self: `${testRealmURL}Pet/${id}`, }, }, - included: [ - { - type: 'card', - id: `${testRealmURL}dir/owner`, - attributes: { - cardDescription: 'Person', - email: null, - posts: null, - cardThumbnailURL: null, - firstName: 'Hassan', - lastName: 'Abdel-Rahman', - cardTitle: 'Hassan Abdel-Rahman', - fullName: 'Hassan Abdel-Rahman', - cardInfo, - }, - meta: { - adoptsFrom: { - module: `${testModuleRealm}person`, - name: 'Person', - }, - lastModified: adapter.lastModifiedMap.get( - `${testRealmURL}dir/owner.json`, - ), - resourceCreatedAt: ownerCreatedAt!, - realmInfo: testRealmInfo, - realmURL: testRealmURL, - }, - links: { - self: `./owner`, - }, - }, - ], }); let fileRef = await adapter.openFile(`Pet/${id}.json`); if (!fileRef) { @@ -1270,8 +1233,6 @@ module('Integration | realm', function (hooks) { }, }); let resourceCreatedAt = await getFileCreatedAt(realm, 'jackie.json'); - let friendCreatedAt = await getFileCreatedAt(realm, 'dir/friend.json'); - let vanGoghCreatedAt = await getFileCreatedAt(realm, 'dir/van-gogh.json'); let response = await handle( realm, new Request(`${testRealmURL}jackie`, { @@ -1318,17 +1279,9 @@ module('Integration | realm', function (hooks) { relationships: { 'pets.0': { links: { self: `./dir/van-gogh` }, - data: { - id: `${testRealmURL}dir/van-gogh`, - type: 'card', - }, }, friend: { links: { self: `./dir/friend` }, - data: { - id: `${testRealmURL}dir/friend`, - type: 'card', - }, }, }, meta: { @@ -1344,63 +1297,6 @@ module('Integration | realm', function (hooks) { resourceCreatedAt: resourceCreatedAt!, }, }, - included: [ - { - type: 'card', - id: `${testRealmURL}dir/friend`, - links: { self: `./friend` }, - attributes: { - cardDescription: 'Person', - email: null, - posts: null, - cardThumbnailURL: null, - firstName: 'Hassan', - lastName: 'Abdel-Rahman', - fullName: 'Hassan Abdel-Rahman', - cardTitle: 'Hassan Abdel-Rahman', - cardInfo, - }, - meta: { - adoptsFrom: { - module: `${testModuleRealm}person`, - name: 'Person', - }, - lastModified: adapter.lastModifiedMap.get( - `${testRealmURL}dir/friend.json`, - ), - resourceCreatedAt: friendCreatedAt!, - realmInfo: testRealmInfo, - realmURL: testRealmURL, - }, - }, - { - type: 'card', - id: `${testRealmURL}dir/van-gogh`, - links: { self: `./van-gogh` }, - attributes: { - firstName: 'Van Gogh', - cardTitle: 'Van Gogh', - cardDescription: null, - cardThumbnailURL: null, - cardInfo, - }, - relationships: { - owner: { links: { self: null } }, - }, - meta: { - adoptsFrom: { - module: `${testModuleRealm}pet`, - name: 'Pet', - }, - lastModified: adapter.lastModifiedMap.get( - `${testRealmURL}dir/van-gogh.json`, - ), - resourceCreatedAt: vanGoghCreatedAt!, - realmInfo: testRealmInfo, - realmURL: testRealmURL, - }, - }, - ], }); let fileRef = await adapter.openFile('jackie.json'); if (!fileRef) { @@ -1537,24 +1433,12 @@ module('Integration | realm', function (hooks) { relationships: { 'pets.0': { links: { self: `./dir/mango` }, - data: { - id: `${testRealmURL}dir/mango`, - type: 'card', - }, }, 'pets.1': { links: { self: `./dir/van-gogh` }, - data: { - id: `${testRealmURL}dir/van-gogh`, - type: 'card', - }, }, friend: { links: { self: `./dir/friend` }, - data: { - id: `${testRealmURL}dir/friend`, - type: 'card', - }, }, }, meta: { @@ -1661,11 +1545,9 @@ module('Integration | realm', function (hooks) { relationships: { 'pets.0': { links: { self: `./dir/mango` }, - data: { id: `${testRealmURL}dir/mango`, type: 'card' }, }, 'pets.1': { links: { self: `./dir/van-gogh` }, - data: { id: `${testRealmURL}dir/van-gogh`, type: 'card' }, }, }, meta: { @@ -1774,7 +1656,6 @@ module('Integration | realm', function (hooks) { assert.deepEqual(json.data.relationships, { 'inners.0.other': { links: { self: `./2` }, - data: { id: `${testRealmURL}2`, type: 'card' }, }, }); assert.deepEqual( @@ -2008,14 +1889,9 @@ module('Integration | realm', function (hooks) { relationships: { 'pets.0': { links: { self: `./dir/van-gogh` }, - data: { id: `${testRealmURL}dir/van-gogh`, type: 'card' }, }, friend: { links: { self: `./dir/different-friend` }, - data: { - id: `${testRealmURL}dir/different-friend`, - type: 'card', - }, }, }, meta: { @@ -2151,17 +2027,9 @@ module('Integration | realm', function (hooks) { relationships: { friend: { links: { self: `./dir/different-friend` }, - data: { - id: `${testRealmURL}dir/different-friend`, - type: 'card', - }, }, 'pets.0': { links: { self: `./dir/van-gogh` }, - data: { - id: `${testRealmURL}dir/van-gogh`, - type: 'card', - }, }, }, meta: { @@ -2271,7 +2139,6 @@ module('Integration | realm', function (hooks) { assert.strictEqual(response.status, 200, 'successful http status'); let json = await response.json(); let mangoCreatedAt = await getFileCreatedAt(realm, 'dir/mango.json'); - let marikoCreatedAt = await getFileCreatedAt(realm, 'dir/mariko.json'); assert.deepEqual(json, { data: { type: 'card', @@ -2288,10 +2155,6 @@ module('Integration | realm', function (hooks) { links: { self: `./mariko`, }, - data: { - type: 'card', - id: `${testRealmURL}dir/mariko`, - }, }, }, meta: { @@ -2310,38 +2173,6 @@ module('Integration | realm', function (hooks) { self: `${testRealmURL}dir/mango`, }, }, - included: [ - { - type: 'card', - id: `${testRealmURL}dir/mariko`, - attributes: { - firstName: 'Mariko', - lastName: 'Abdel-Rahman', - fullName: 'Mariko Abdel-Rahman', - cardTitle: 'Mariko Abdel-Rahman', - cardDescription: 'Person', - email: null, - posts: null, - cardThumbnailURL: null, - cardInfo, - }, - meta: { - adoptsFrom: { - module: `${testModuleRealm}person`, - name: 'Person', - }, - lastModified: adapter.lastModifiedMap.get( - `${testRealmURL}dir/mariko.json`, - ), - resourceCreatedAt: marikoCreatedAt!, - realmInfo: testRealmInfo, - realmURL: testRealmURL, - }, - links: { - self: `./mariko`, - }, - }, - ], }); let fileRef = await adapter.openFile('dir/mango.json'); if (!fileRef) { diff --git a/packages/realm-server/tests/card-endpoints-test.ts b/packages/realm-server/tests/card-endpoints-test.ts index 1fe15eac391..5888296acf0 100644 --- a/packages/realm-server/tests/card-endpoints-test.ts +++ b/packages/realm-server/tests/card-endpoints-test.ts @@ -21,6 +21,7 @@ import { rri, SKIP_INDEX_WAIT_HEADER, searchEntryWireQueryFromQuery, + setWriteTimingSinkForTests, type LooseSingleCardDocument, type SingleCardDocument, } from '@cardstack/runtime-common'; @@ -1733,6 +1734,59 @@ module(basename(import.meta.filename), function () { let { getMessagesSince } = setupMatrixRoom(hooks, getRealmSetup); + // The create path reads the new card back through its own call, so the + // shape it answers with is asserted separately from the patch path's. + // The read of the card the create just made is the control: it is what + // the create would have assembled had it asked. + test('a create side-loads none of the new card’s links', async function (assert) { + let write = await request + .post('/') + .send({ + data: { + type: 'card', + attributes: { firstName: 'Mango' }, + relationships: { + friend: { links: { self: `${testRealmHref}hassan` } }, + }, + meta: { + adoptsFrom: { + module: rri(`${testRealmHref}friend.gts`), + name: 'Friend', + }, + }, + }, + }) + .set('Accept', 'application/vnd.card+json'); + + assert.strictEqual(write.status, 201, `HTTP 201: ${write.text}`); + // The stored link survives; what a readback would have added on top + // of it — the resolved target, and the target's own resource — does + // not. + assert.ok( + write.body.data.relationships?.friend?.links?.self, + 'the create still names the card its link points at', + ); + assert.notOk( + write.body.included, + 'but carries no side-loaded resources', + ); + + let localPath = new URL(write.body.data.id).pathname.replace( + new URL(testRealmHref).pathname, + '', + ); + let read = await request + .get(`/${localPath}`) + .set('Accept', 'application/vnd.card+json'); + assert.strictEqual(read.status, 200, `HTTP 200: ${read.text}`); + assert.ok( + (read.body.included ?? []).some( + (resource: any) => resource.id === `${testRealmHref}hassan`, + ), + 'the read of the created card does side-load that link', + ); + }); + test('serves the request', async function (assert) { let realmEventTimestampStart = Date.now(); @@ -3185,6 +3239,113 @@ module(basename(import.meta.filename), function () { let { getMessagesSince } = setupMatrixRoom(hooks, getRealmSetup); + // `hassan` links to `jade`, which links back — so a closure walk over + // this card has something to find and does not terminate at one layer. + // The read is the control: it is what the write would have assembled. + test('a write side-loads none of the written card’s links', async function (assert) { + let write = await request + .patch('/hassan') + .send({ + data: { + type: 'card', + attributes: { firstName: 'Hassan Abdel-Rahman' }, + meta: { + adoptsFrom: { module: rri('./friend.gts'), name: 'Friend' }, + }, + }, + }) + .set('Accept', 'application/vnd.card+json'); + + assert.strictEqual(write.status, 200, `HTTP 200: ${write.text}`); + assert.strictEqual( + write.body.data.attributes.firstName, + 'Hassan Abdel-Rahman', + 'the write answers with the value it stored', + ); + assert.strictEqual( + write.body.data.relationships?.friend?.links?.self, + './jade', + 'and still names the card the stored link points at', + ); + assert.notOk( + write.body.included, + 'but carries no side-loaded resources', + ); + + let read = await request + .get('/hassan') + .set('Accept', 'application/vnd.card+json'); + assert.strictEqual(read.status, 200, `HTTP 200: ${read.text}`); + assert.ok( + (read.body.included ?? []).some( + (resource: any) => resource.id === `${testRealmHref}jade`, + ), + 'the read of the same card does side-load that link', + ); + }); + + // Each of these stages can be the whole of a slow write, and none is + // distinguishable from outside the handler, so the line has to carry + // every one of them for a write's duration to be attributable. + test('a write reports where its time went', async function (assert) { + let lines: string[] = []; + setWriteTimingSinkForTests((line) => lines.push(line)); + try { + let response = await request + .patch('/hassan') + .send({ + data: { + type: 'card', + // A value the fixture does not already hold: an unchanged + // patch short-circuits before the write, and the stages + // asserted below are the ones that short circuit skips. + attributes: { firstName: 'Hassan Timed' }, + meta: { + adoptsFrom: { module: rri('./friend.gts'), name: 'Friend' }, + }, + }, + }) + .set('Accept', 'application/vnd.card+json') + .set('X-Boxel-Logging-Correlation-Id', 'write-timing-probe'); + + assert.strictEqual( + response.status, + 200, + `HTTP 200: ${response.text}`, + ); + } finally { + setWriteTimingSinkForTests(undefined); + } + + assert.strictEqual(lines.length, 1, 'the write emitted one line'); + let line = lines[0]; + assert.ok( + line.startsWith('PATCH '), + `line names the method: ${line}`, + ); + assert.ok( + line.includes('corr=write-timing-probe'), + `line carries the caller's correlation id: ${line}`, + ); + for (let stage of [ + 'lock', + 'drain', + 'stage', + 'write', + 'readback', + 'stringify', + ]) { + assert.ok( + new RegExp(`\\b${stage}=\\d+`).test(line), + `line attributes the ${stage} stage: ${line}`, + ); + } + assert.ok( + /\bhandler=\d+ms\b/.test(line), + `line reports the whole handler: ${line}`, + ); + }); + // What is stored for a relationship depends on whether the link can be // relativized against the writing realm. A scoped reference cannot be, // and must not be resolved either: resolving one stores whatever URL @@ -3516,9 +3677,15 @@ module(basename(import.meta.filename), function () { test('PATCH response carries an ETag and writes invalidate the previous one', async function (assert) { // Capture the pre-patch ETag, mutate the card, and verify the PATCH - // response advertises a *different* ETag for the new state — that's - // the contract that lets the caller cache the post-patch body - // without an extra round-trip GET. + // response advertises a different ETag for the new state. + // + // A write answers with the written card alone while a GET answers + // with its link closure, so the two are different representations of + // one card and take different validators. That is what the + // `write-echo` variant records, and it is why the ETag a PATCH + // returns does not short-circuit a later GET of the same URL: being + // 304'd on it would hand the caller a body with no `included[]` as + // though it were the GET representation. let initialResponse = await request .get('/person-1') .set('Accept', 'application/vnd.card+json'); @@ -3545,8 +3712,8 @@ module(basename(import.meta.filename), function () { let patchEtag = patchResponse.get('etag') ?? ''; assert.ok(patchEtag, 'PATCH response carries an ETag'); assert.true( - /^"\d+(?:-[0-9a-f]+)?:card-rri"$/.test(patchEtag), - `PATCH ETag matches "(-)?:card-rri" pattern (got ${patchEtag})`, + /^"\d+(?:-[0-9a-f]+)?:card-rri-write-echo"$/.test(patchEtag), + `PATCH ETag names the write-echo shape (got ${patchEtag})`, ); assert.notStrictEqual( patchEtag, @@ -3565,25 +3732,46 @@ module(basename(import.meta.filename), function () { 200, 'old ETag no longer matches → fresh 200', ); - assert.strictEqual( + assert.true( + /^"\d+(?:-[0-9a-f]+)?:card-rri"$/.test( + staleResponse.get('etag') ?? '', + ), + `GET reports a validator for the read shape (got ${staleResponse.get('etag')})`, + ); + assert.notStrictEqual( staleResponse.get('etag'), - patchEtag, - 'GET reports the new ETag', + originalEtag, + 'and it advanced with the write', ); - // And the new etag from the PATCH must short-circuit on next GET. - let cachedResponse = await request + // The PATCH's own validator describes the write echo, which carries + // no `included[]`, so it must not satisfy a GET — a 304 here would + // leave the caller holding the narrower body as the card's read + // representation. + let echoValidated = await request .get('/person-1') .set('Accept', 'application/vnd.card+json') .set('If-None-Match', patchEtag); + assert.strictEqual( + echoValidated.status, + 200, + 'the write echo’s ETag does not short-circuit a GET', + ); + + // The GET's own validator still does. + let freshEtag = echoValidated.get('etag') ?? ''; + let cachedResponse = await request + .get('/person-1') + .set('Accept', 'application/vnd.card+json') + .set('If-None-Match', freshEtag); assert.strictEqual( cachedResponse.status, 304, - 'new ETag from PATCH lets a follow-up GET short-circuit', + 'the ETag a GET returns lets a follow-up GET short-circuit', ); }); - test('no-op PATCH response carries an ETag matching the existing one', async function (assert) { + test('no-op PATCH response carries the write-echo validator over the unchanged state', async function (assert) { // Prime once so the stored file is in canonical serialized form; // the no-op assertions below measure the steady state (see the // no-op lastModified test). @@ -3623,10 +3811,20 @@ module(basename(import.meta.filename), function () { .set('Accept', 'application/vnd.card+json'); assert.strictEqual(patchResponse.status, 200, 'no-op PATCH succeeds'); + // Nothing was rewritten, so `indexed_at` has not moved and the + // validator is built over the same state the GET described. It is + // still a different validator, because a no-op PATCH answers with + // the write-echo shape like any other write — which is what keeps a + // caller from treating the echo as the card's read representation. assert.strictEqual( + patchResponse.get('etag'), + (initialEtag ?? '').replace(/:card-rri"$/, ':card-rri-write-echo"'), + 'no-op PATCH validates the unchanged state under the write-echo shape', + ); + assert.notStrictEqual( patchResponse.get('etag'), initialEtag, - 'no-op PATCH returns the same ETag (no rewrite, indexed_at unchanged)', + 'and so does not collide with the validator a GET returns', ); }); @@ -6338,6 +6536,59 @@ boxel: ); }); + // A write is answered from the written card alone. The read of the same + // card in the same test is the control: it is what the card's query-backed + // fields resolve to, and what the write would have assembled had it asked. + test('a write does not resolve the written card’s query-backed fields', async function (assert) { + let read = await consumerRequest + .get('/favorite') + .set('Accept', 'application/vnd.card+json'); + assert.strictEqual(read.status, 200, `HTTP 200: ${read.text}`); + assert.ok( + read.body.data.relationships?.favorite?.links?.search, + 'the read resolves the query-backed field', + ); + assert.ok( + (read.body.included ?? []).some( + (resource: any) => resource.id === `${consumerRealmURL}local-person`, + ), + 'and side-loads the card that field found', + ); + + let write = await consumerRequest + .patch('/favorite') + .send({ + data: { + type: 'card', + attributes: { cardInfo: { name: 'Renamed' } }, + meta: { + adoptsFrom: { + module: rri('./favorite-finder'), + name: 'FavoriteLookup', + }, + }, + }, + }) + .set('Accept', 'application/vnd.card+json'); + + assert.strictEqual(write.status, 200, `HTTP 200: ${write.text}`); + assert.strictEqual( + write.body.data.id, + `${consumerRealmURL}favorite`, + 'the write answers about the card it wrote', + ); + assert.strictEqual( + write.body.data.attributes.cardInfo.name, + 'Renamed', + 'and answers with the value it just stored', + ); + assert.notOk( + write.body.data.relationships?.favorite?.links?.search, + 'but runs no query for the query-backed field', + ); + assert.notOk(write.body.included, 'and side-loads nothing'); + }); + test('linksToMany query returns remote results and records errors for failing realm', async function (assert) { let response = await consumerRequest .get('/favorite') diff --git a/packages/runtime-common/card-operations/coordinator.ts b/packages/runtime-common/card-operations/coordinator.ts index f1b88300bdd..2e1c4b03894 100644 --- a/packages/runtime-common/card-operations/coordinator.ts +++ b/packages/runtime-common/card-operations/coordinator.ts @@ -42,6 +42,7 @@ import { type OperationIdentityResult, } from './types.ts'; import type { CodeRef } from '../code-ref.ts'; +import type { RequestTimings } from '../request-timings.ts'; import type { Definition } from '../definitions.ts'; import type { LooseSingleCardDocument } from '../index.ts'; import type { RealmResourceIdentifier } from '../realm-identifiers.ts'; @@ -227,6 +228,13 @@ export interface CommitBatchOptions { // and answered success: serialization records a link it cannot resolve as // an explicit null. foreignSideLoadLink?: 'refuse' | 'leave'; + // Per-request wall-clock collector, threaded from a caller that reports + // where its write's time went. The stages a commit owns are not observable + // from outside it — waiting for the realm's write lock and draining + // indexing already in flight both happen before the caller's own work + // starts, and either can be the whole of a slow write — so they are stamped + // here or not at all. Absent, and so a no-op, for every other caller. + timings?: RequestTimings; } // One entry's answer, in the order the entries were sent. A write reports the @@ -246,7 +254,15 @@ export async function commitBatch( // tell every subscriber that something changed. return []; } + // Stamped from outside the lock so the wait for it is its own stage: a + // batch queued behind the realm's other writers spends its time here, and + // from the handler that is indistinguishable from slow indexing. + let lockRequestedAt = Date.now(); + let timings = opts.timings; + let timed = (stage: string, fn: () => Promise): Promise => + timings ? timings.time(stage, fn) : fn(); return await core.withWriteLock(async () => { + timings?.add('lock', Date.now() - lockRequestedAt); // Drained inside the lock, before anything is staged. Staging serializes // each card against its type's definition, and a module written moments // earlier may still be indexing; without this a batch that follows a @@ -282,62 +298,72 @@ export async function commitBatch( // issued while a bulk import drains would park here holding it, with // every other writer queued behind. if (opts.waitForIndex !== false && entries.some(stagesContent)) { - await core.drainIndexing(); + await timed('drain', () => core.drainIndexing()); } - // Every `lid` in the batch resolves to a URL before any executor runs. A - // created card's file is named after its `lid`, so its URL is path math - // over the type it adopts — no read and no write — which is what lets an - // entry link to a card a later entry mints. - let { lids, foreignLids } = indexLids(entries, paths); - let { stored, storedMeta } = await readPreState(core, entries, paths); - // What an append stages for a file it never read whole. Kept beside - // `stored` rather than in it: the two describe the same file in different - // terms, and an executor that needs one cannot work from the other. - let splices = new Map(); let staged: StagedChange[] = []; // The version each entry's merge was computed over, captured as it stages // rather than read back at the end: `stored` moves underneath the batch // as entries compose, so by the commit it no longer holds what the first // entry to touch a file merged over. let baseHashes: (string | undefined)[] = []; - for (let [index, entry] of entries.entries()) { - let change = await stageEntry(entry, index, { - realmURL: core.realmURL, - paths, - lids, - foreignLids, - foreignSideLoadLink: opts.foreignSideLoadLink, - stored, - storedMeta, - splices, - openSourceBytes: core.openSourceBytes, - fileExists: core.fileExists, - indexedCardValues: core.indexedCardValues, - actor: opts.actor ?? '', - serializeCard: core.serializeCard, - codeRefKey: core.codeRefKey, - resolveModuleId: core.resolveModuleId, - storedLink: core.storedLink, - resolvedLink: core.resolvedLink, - lookupDefinition: core.lookupDefinition, - }); - baseHashes.push( - change.primaryPath - ? (stored.get(change.primaryPath)?.contentHash ?? - storedMeta.get(change.primaryPath)?.contentHash) - : undefined, - ); - compose(stored, storedMeta, splices, entry, change); - staged.push(change); + // Stamped from a `finally`: an entry that cannot be carried out throws + // from the staging work, and a write that failed is exactly the one whose + // time someone is trying to account for. + let stageStart = Date.now(); + try { + // Every `lid` in the batch resolves to a URL before any executor runs. A + // created card's file is named after its `lid`, so its URL is path math + // over the type it adopts — no read and no write — which is what lets an + // entry link to a card a later entry mints. + let { lids, foreignLids } = indexLids(entries, paths); + let { stored, storedMeta } = await readPreState(core, entries, paths); + // What an append stages for a file it never read whole. Kept beside + // `stored` rather than in it: the two describe the same file in different + // terms, and an executor that needs one cannot work from the other. + let splices = new Map(); + for (let [index, entry] of entries.entries()) { + let change = await stageEntry(entry, index, { + realmURL: core.realmURL, + paths, + lids, + foreignLids, + foreignSideLoadLink: opts.foreignSideLoadLink, + stored, + storedMeta, + splices, + openSourceBytes: core.openSourceBytes, + fileExists: core.fileExists, + indexedCardValues: core.indexedCardValues, + actor: opts.actor ?? '', + serializeCard: core.serializeCard, + codeRefKey: core.codeRefKey, + resolveModuleId: core.resolveModuleId, + storedLink: core.storedLink, + resolvedLink: core.resolvedLink, + lookupDefinition: core.lookupDefinition, + }); + baseHashes.push( + change.primaryPath + ? (stored.get(change.primaryPath)?.contentHash ?? + storedMeta.get(change.primaryPath)?.contentHash) + : undefined, + ); + compose(stored, storedMeta, splices, entry, change); + staged.push(change); + } + assertWritesAllowed(staged); + assertLinkedCardsSurvive(staged, paths); + assertWritesFit(core, staged); + await assertRemovalsAllowed(core, paths, staged); + await assertDestinationsFree(core, staged); + } finally { + timings?.add('stage', Date.now() - stageStart); } - assertWritesAllowed(staged); - assertLinkedCardsSurvive(staged, paths); - assertWritesFit(core, staged); - await assertRemovalsAllowed(core, paths, staged); - await assertDestinationsFree(core, staged); // Everything above either produced bytes for every entry or threw, and a // throw leaves the realm as it was. - return await commitStaged(core, entries, staged, baseHashes, opts); + return await timed('write', () => + commitStaged(core, entries, staged, baseHashes, opts), + ); }); } diff --git a/packages/runtime-common/index.ts b/packages/runtime-common/index.ts index 35928d28e0b..0da7bb5853d 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-timing.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 d8e4b49ea10..184c3e00ce4 100644 --- a/packages/runtime-common/realm.ts +++ b/packages/runtime-common/realm.ts @@ -252,6 +252,8 @@ import { sanitizeLoggingCorrelationId, X_BOXEL_LOGGING_CORRELATION_ID_HEADER, } from './prerender-headers.ts'; +import { RequestTimings } from './request-timings.ts'; +import { emitWriteTiming } from './write-timing.ts'; import { type MatrixClient, ensureFullMatrixUserId, @@ -835,11 +837,29 @@ function buildEtag( // any card); the screenshots fingerprint captures the joined // `meta.screenshots` (see `screenshotsEtagFingerprint`). A null // `indexedAt` suppresses ETag emission entirely. +// +// How much of a card's link graph a card+json body carries. `full` side-loads +// the whole closure; `links-only` answers the relationships without +// side-loading their targets; `write-echo` is what a POST / PATCH returns — +// the written card alone, neither its links resolved nor its query-backed +// fields expanded, because nothing reads either off a write response. +// +// These three take different validators because a client holding one must not +// be 304'd to another's body. They are not the only way a body can vary at +// one `indexed_at`: a read from inside a prerender leaves query-backed fields +// unexpanded while still side-loading static links, and that body shares +// `full`'s validator deliberately — it is never served to a client that +// caches, and the response cache separates it by folding +// `skipQueryBackedExpansion` into its own key rather than into the ETag. +// Adding a member here is the wrong move for a variation the validator does +// not have to carry. +type CardJsonShape = 'full' | 'links-only' | 'write-echo'; + function buildCardJsonEtag( indexedAt: number | null | undefined, realmInfoHash: string | undefined, screenshotsFingerprint?: string, - resolveLinksOnly = false, + shape: CardJsonShape = 'full', ): string | undefined { if (indexedAt == null) { return undefined; @@ -847,17 +867,17 @@ function buildCardJsonEtag( let base = [`${indexedAt}`, realmInfoHash, screenshotsFingerprint] .filter(Boolean) .join('-'); - // A read that answers relationships without side-loading their targets + // A response that carries less of the card's link graph than a full read // serves a different representation of the same card at the same // `indexed_at`, so it takes its own variant — the same job the constant - // does for a serialization change, on a value that varies per server - // rather than per revision. Without it, turning the setting on or off - // would leave every client that holds a validator being 304'd to the - // shape it cached, and the two shapes reachable under one key in the - // response cache. - let variant = resolveLinksOnly - ? `${CARD_JSON_ETAG_VARIANT}-links-only` - : CARD_JSON_ETAG_VARIANT; + // does for a serialization change, on a value that varies per response + // rather than per revision. Without it, a client that cached a narrower + // shape would be 304'd to it when it later asks for the full one, and the + // shapes would be reachable under one key in the response cache. + let variant = + shape === 'full' + ? CARD_JSON_ETAG_VARIANT + : `${CARD_JSON_ETAG_VARIANT}-${shape}`; return `"${base}:${variant}"`; } @@ -7582,9 +7602,53 @@ export class Realm { return notFound(request, requestContext); } + // One `realm:write-timing` line per card write, emitted from a `finally` so + // a write that failed is attributed too — that is the write whose time + // someone is most likely trying to account for. + // + // A request that was refused before it reached the commit — an unsupported + // media type, a path the verb does not serve, a body that is not a card — + // stamped no stage, and a line for it would say only how long it took to + // say no. Those are skipped, so every line on this channel describes a + // request that tried to write. + #emitWriteTiming( + method: string, + request: Request, + startedAt: number, + timings: RequestTimings, + ): void { + let stages = timings.toLogFragment(); + if (!stages) { + return; + } + let correlationId = sanitizeLoggingCorrelationId( + request.headers.get(X_BOXEL_LOGGING_CORRELATION_ID_HEADER), + ); + emitWriteTiming( + `${method} ${request.url}` + + (correlationId ? ` corr=${correlationId}` : '') + + ` handler=${Date.now() - startedAt}ms ` + + stages, + ); + } + private async createCard( request: Request, requestContext: RequestContext, + ): Promise { + let timings = new RequestTimings(); + let startedAt = Date.now(); + try { + return await this.#createCard(request, requestContext, timings); + } finally { + this.#emitWriteTiming('POST', request, startedAt, timings); + } + } + + async #createCard( + request: Request, + requestContext: RequestContext, + timings: RequestTimings, ): Promise { let duringPrerender = isDuringPrerenderRequest(request); // A skip-index-wait caller (see SKIP_INDEX_WAIT_HEADER) gets the same @@ -7675,6 +7739,7 @@ export class Realm { // create, and a `POST` carrying one has always stored the card // with that edge empty rather than refusing the write. foreignSideLoadLink: 'leave', + timings, }, ) )[0]; @@ -7712,12 +7777,25 @@ export class Realm { } doc = await this.serializedInstanceEcho(stored, newURL, lastModified); } else { - let entry = await this.#realmIndexQueryEngine.cardDocument( - new URL(newURL), - { - loadLinks: true, - skipQueryBackedExpansion: false, - }, + // The readback asks for the written card and nothing around it: no + // `loadLinks`, so neither the transitive closure of the card's links nor + // the query a query-backed field would run to name its targets. + // + // Nothing consumes either. Two surfaces in the host see a write + // response, and neither reads the link graph. The one that updates the + // instance drops `data.attributes` and `data.relationships` before + // merging, which leaves `included[]` unreachable; the save subscriber + // gets the body whole, and exists for tests. A card created by `lid` + // under this write is reconciled to its assigned id from the realm + // invalidation event, which correlates the last segment of the assigned + // URL with the local id (`tryFindingCardItem` in the host's card store + // names that as the reconciliation point, alongside `api.setId`); the + // response document is not part of that path, and could not be — the + // index answers in ids, never in the `lid` a caller would match on. + // Writes that answer from the serialized echo — prerender and + // skip-index-wait callers — return no `included` at all and always have. + let entry = await timings.time('readback', () => + this.#realmIndexQueryEngine.cardDocument(new URL(newURL)), ); if (!entry || entry?.type === 'error') { let err = entry @@ -7738,8 +7816,14 @@ export class Realm { }); } this.#serveInstanceIdsAsRRI(doc); + // The last sequential leg: turning the assembled document into the bytes + // that go on the wire. Stamped because it scales with the body, which is + // what the shape of this response decides. + let responseBody = await timings.time('stringify', async () => + JSON.stringify(doc, null, 2), + ); return createResponse({ - body: JSON.stringify(doc, null, 2), + body: responseBody, init: { status: 201, headers: { @@ -7755,6 +7839,20 @@ export class Realm { private async patchCardInstance( request: Request, requestContext: RequestContext, + ): Promise { + let timings = new RequestTimings(); + let startedAt = Date.now(); + try { + return await this.#patchCardInstance(request, requestContext, timings); + } finally { + this.#emitWriteTiming('PATCH', request, startedAt, timings); + } + } + + async #patchCardInstance( + request: Request, + requestContext: RequestContext, + timings: RequestTimings, ): Promise { let localPath = this.paths.local(new URL(request.url)); if (await this.nonJsonFileExists(localPath)) { @@ -7842,6 +7940,7 @@ export class Realm { // The same reading a create takes of a side-load claiming another // realm: the edge is stored empty and the patch succeeds. foreignSideLoadLink: 'leave', + timings, }, ) )[0]; @@ -7865,23 +7964,30 @@ export class Realm { }); } let created = result.meta.created; - let readEntry = async (skipQueryBackedExpansion: boolean) => - await this.#realmIndexQueryEngine.cardDocument(new URL(instanceURL), { - loadLinks: true, - skipQueryBackedExpansion, - }); + // The card and nothing around it: no `loadLinks`, so neither the + // transitive closure of its links nor the query a query-backed field + // would run to name its targets. Nothing consumes either off a write + // response — the create path's readback states the case. The commit has + // released the write lock by the time this runs, so what it costs is the + // writer's own latency rather than every other writer's. + let readEntry = async () => + await timings.time('readback', () => + this.#realmIndexQueryEngine.cardDocument(new URL(instanceURL)), + ); let doc: SingleCardDocument; if (!result.meta.changed) { // The patch left the card exactly as it was, so the answer is the card // as the realm already holds it — read before anything else is decided, // because a request that changed nothing is answered from the index - // whether or not it asked for its own indexing to be deferred. Only a - // render's own read narrows what it resolves. - let unchanged = await readEntry(duringPrerender); + // whether or not it asked for its own indexing to be deferred. It is + // still answering a writer, so it takes the same narrow shape every + // other write does. + let unchanged = await readEntry(); if (unchanged && unchanged.type !== 'error') { return await this.#patchedCardResponse(unchanged, { instanceURL, localPath, + timings, // The file was not rewritten, so the modification time it carries is // the one the index recorded for it. lastModified: unchanged.doc.data.meta.lastModified ?? lastModified, @@ -7937,7 +8043,7 @@ export class Realm { requestContext, }); } - let entry = await readEntry(false); + let entry = await readEntry(); if (entry && entry.type !== 'error') { return await this.#patchedCardResponse(entry, { instanceURL, @@ -7945,6 +8051,7 @@ export class Realm { lastModified, created, requestContext, + timings, }); } let stored = storedCardDocument(result); @@ -8006,12 +8113,14 @@ export class Realm { lastModified, created, requestContext, + timings, }: { instanceURL: string; localPath: LocalPath; lastModified: number | null; created: number | null; requestContext: RequestContext; + timings: RequestTimings; }, ): Promise { let doc: SingleCardDocument = merge({}, entry.doc, { @@ -8023,6 +8132,8 @@ export class Realm { // The PATCH echo carries the joined `meta.screenshots` like a GET does — // the store replaces an instance's meta wholesale from a save response, so // an echo without it would wipe the key client-side until the next GET. + // The two representations part company on the link graph only, which is + // what the `write-echo` validator variant below records. if (entry.screenshots) { doc.data.meta = { ...doc.data.meta, @@ -8042,10 +8153,17 @@ export class Realm { entry.indexedAt, this.getCachedRealmInfoHash(), screenshotsEtagFingerprint(entry.screenshots), + 'write-echo', ); this.#serveInstanceIdsAsRRI(doc); + // The last sequential leg: turning the assembled document into the bytes + // that go on the wire. Stamped because it scales with the body, which is + // what the shape of this response decides. + let body = await timings.time('stringify', async () => + JSON.stringify(doc, null, 2), + ); return createResponse({ - body: JSON.stringify(doc, null, 2), + body, init: { headers: { 'content-type': SupportedMimeType.CardJson, @@ -8403,7 +8521,7 @@ export class Realm { result.indexedAt, this.getCachedRealmInfoHash(), screenshotsEtagFingerprint(result.screenshots), - resolveLinksOnly, + resolveLinksOnly ? 'links-only' : 'full', ); let cacheControl = this.cardJsonCacheControl(requestContext); let lastModified: Record = @@ -8580,7 +8698,7 @@ export class Realm { instanceEntry.indexedAt, realmInfoHash, screenshotsEtagFingerprint(instanceEntry.screenshots), - resolveLinksOnly, + resolveLinksOnly ? 'links-only' : 'full', ); } if ( @@ -8771,7 +8889,7 @@ export class Realm { headers.indexedAt, this.getCachedRealmInfoHash(), screenshotsEtagFingerprint(headers.screenshots), - resolveLinksOnly, + resolveLinksOnly ? 'links-only' : 'full', ); return { kind: 'document', diff --git a/packages/runtime-common/write-timing.ts b/packages/runtime-common/write-timing.ts new file mode 100644 index 00000000000..97c8621f183 --- /dev/null +++ b/packages/runtime-common/write-timing.ts @@ -0,0 +1,52 @@ +import { logger } from './log.ts'; + +// The write-path counterpart of `realm:search-timing`: one line per card+json +// POST / PATCH, attributing the request's server-side wall-clock across the +// stages a write runs through. +// +// Each stage can be the whole of a slow write, and they are not +// distinguishable from outside: +// +// lock waiting for the realm's write lock, i.e. queueing behind the +// realm's other writers +// drain waiting for indexing already in flight +// stage reading the pre-state and running the entries' executors +// write committing the bytes, plus this write's own indexing unless +// the caller opted out +// readback reading the written card back out of the index +// stringify serializing the response document +// +// A write whose duration exceeds its own indexing job's is explained by +// which of these it spent the difference in; without them the remainder is +// unattributable. +// +// Unlike search timing this is not gated on the caller sending a correlation +// id. Writes are a small fraction of a realm's requests — hundreds an hour +// against tens of thousands of reads — so emitting for every write costs +// little, and a slow write is rarely one that was instrumented in advance. A +// correlation id, when the caller sends one, is stamped on the line so it +// joins that request's `realm:requests` entry. +// +// Indirection so a test can deterministically capture the emitted line: +// loglevel rebinds a logger's methods on every `setLevel`, so a test that +// monkeypatched a direct logger handle would race the next +// `logger('realm:write-timing')` call. A settable sink sidesteps that, the +// same way `emitSearchTiming` does. +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); +}