From 4b71144488b142c409b330807c0418acb8b1b1ce Mon Sep 17 00:00:00 2001 From: Brian Warner Date: Wed, 8 Feb 2023 15:27:53 -0800 Subject: [PATCH] add transcript pseudo-events: init, snapshot save/load, shutdown This introduces four new pseudo-delivery events to the transcript: * 'initialize-worker': a new empty worker is created * 'load-snapshot': a worker is loaded from heap snapshot * 'save-snapshot': we tell the worker to write a heap snapshot * 'shutdown-worker': we stop the worker (e.g. during upgrade) These events are not actually delivered to the worker: they are not VatDeliveryObjects. However many of them are implemented with commands to the worker (but not `deliver()` commands). The vat-warehouse records these events in the transcript to help subsequent manual/external replay tools know what happened. Without them, we'd need to deduce e.g. the heap-snapshot writing schedule by counting deliveries and comparing them against snapshot initial/interval. The 'save-snapshot'/'load-snapshot' pair indicates what a replay would do. It does not mean that the vat-warehouse actually tore down the old worker and immediately replaced it with a new one (from snapshot). It might choose to do that, or the worker itself might choose to replace its XS engine instance with a fresh one, or it might keep using the old engine. The 'save-snapshot' command has side-effects (it does a forced GC), so it is important to keep track of when it happened. As before, the transcript is broken up into "spans", delimited by heap snapshots or upgrade-related shutdowns. To bring a worker up to date, we want to start a worker (either a blank one, or from a snapshot), and then replay the "current span". With this change, the current span always starts either with 'initialize-worker' or with 'load-snapshot', telling us exactly what needs to be done. The span then contains all the deliveries that must be replayed. Old spans will end with `save-snapshot` or `shutdown-worker`, but the current span will never include one of those: the span is closed immediately after those events are added. When the kernel replays a transcript to bring a worker up to date, that replay will never see 'save-snapshot' or 'shutdown-worker'. But an external tool which replays a historical span will see them at the end. The `initialize-worker` event contains `workerOptions` (which includes which type of worker is being used, as well as helper bundle IDs like lockdown and supervisor), as well as the `source.bundleID` for the vat bundle. The `save-snapshot` event results contain the `snapshotID` hash that was generated. The `load-snapshot` event includes the `snapshotID` in a record that could be extended with additional details in the future (like an xsnap version). The types were improved to make `TranscriptDelivery` be a superset of `VatDeliveryObject`. We also record TranscriptDeliveryResult, which is currently a stripped down subset of VatDeliveryResult (just the "ok" status), plus the save-snapshot hash. In the future, we'll probably record the deterministic subset of metering results (computrons, maybe something about memory allocation). In the slog, the `heap-snapshot-save` event details now contain `snapshotID` instead of `hash`, to be consistent. Previously vat-warehouse used `lastVatID` to track which vat received a delivery most recently, and `saveSnapshot()` used that to decide which vat requires a snapshot. This commit changes that path to be more explicit, and removes `lastVatID`. refs #7199 refs #6770 --- packages/SwingSet/src/kernel/kernel.js | 13 +- .../SwingSet/src/kernel/state/vatKeeper.js | 62 +++- packages/SwingSet/src/kernel/vat-warehouse.js | 122 +++++-- packages/SwingSet/src/types-internal.js | 19 +- packages/SwingSet/test/test-controller.js | 36 +- packages/SwingSet/test/test-kernel.js | 49 +-- .../transcript/test-transcript-entries.js | 317 ++++++++++++++++++ .../transcript/vat-bootstrap-transcript.js | 15 + .../vat-warehouse/test-reload-snapshot.js | 41 ++- .../test-stable-bundles.js | 13 +- 10 files changed, 592 insertions(+), 95 deletions(-) create mode 100644 packages/SwingSet/test/transcript/test-transcript-entries.js create mode 100644 packages/SwingSet/test/transcript/vat-bootstrap-transcript.js diff --git a/packages/SwingSet/src/kernel/kernel.js b/packages/SwingSet/src/kernel/kernel.js index 1a74c807faab..6a4a4e601101 100644 --- a/packages/SwingSet/src/kernel/kernel.js +++ b/packages/SwingSet/src/kernel/kernel.js @@ -373,7 +373,7 @@ export default function buildKernel( * @typedef { { * abort?: boolean, // changes should be discarded, not committed * consumeMessage?: boolean, // discard the aborted delivery - * didDelivery?: boolean, // we made a delivery to a vat, for run policy + * didDelivery?: VatID, // we made a delivery to a vat, for run policy and save-snapshot * computrons?: BigInt, // computron count for run policy * meterID?: string, // deduct those computrons from a meter * decrementReapCount?: { vatID: VatID }, // the reap counter should decrement @@ -462,7 +462,7 @@ export default function buildKernel( // TODO metering.allocate, some day /** @type {CrankResults} */ - const results = { didDelivery: true, computrons }; + const results = { didDelivery: vatID, computrons }; if (meterID && computrons) { results.meterID = meterID; // decrement meter when we're done @@ -702,7 +702,7 @@ export default function buildKernel( console.log('error during createDynamicVat', err); const info = makeError(`${err}`); const results = { - didDelivery: true, // ok, it failed, but we did spend the time + didDelivery: vatID, // ok, it failed, but we did spend the time abort: true, // delete partial vat state consumeMessage: true, // don't repeat createVat terminate: { vatID, reject: true, info }, @@ -1266,8 +1266,11 @@ export default function buildKernel( crankResults.consumeMessage ? 'deliver' : 'start', ); } else { - // eslint-disable-next-line @jessie.js/no-nested-await - await vatWarehouse.maybeSaveSnapshot(); + const vatID = crankResults.didDelivery; + if (vatID) { + // eslint-disable-next-line @jessie.js/no-nested-await + await vatWarehouse.maybeSaveSnapshot(vatID); + } } const { computrons, meterID } = crankResults; if (computrons) { diff --git a/packages/SwingSet/src/kernel/state/vatKeeper.js b/packages/SwingSet/src/kernel/state/vatKeeper.js index d52a816f289f..49b1890d3474 100644 --- a/packages/SwingSet/src/kernel/state/vatKeeper.js +++ b/packages/SwingSet/src/kernel/state/vatKeeper.js @@ -21,6 +21,8 @@ import { enumeratePrefixedKeys } from './storageHelper.js'; * @typedef { import('../../types-internal.js').VatManager } VatManager * @typedef { import('../../types-internal.js').RecordedVatOptions } RecordedVatOptions * @typedef { import('../../types-internal.js').TranscriptEntry } TranscriptEntry + * @typedef {import('../../types-internal.js').TranscriptDeliverySaveSnapshot} TDSaveSnapshot + * @typedef {import('../../types-internal.js').TranscriptDeliveryLoadSnapshot} TDLoadSnapshot */ // makeVatKeeper is a pure function: all state is kept in the argument object @@ -463,16 +465,28 @@ export function makeVatKeeper( } } + function transcriptSize() { + const bounds = transcriptStore.getCurrentSpanBounds(vatID); + const { startPos, endPos } = bounds; + return endPos - startPos; + } + /** - * Generator function to return the vat's transcript, one entry at a time. + * Generator function to return the vat's current-span transcript, + * one entry at a time. * - * @param {number} [startPos] Optional position to begin reading from - * - * @yields { TranscriptEntry } a stream of transcript entries + * @yields { [number, TranscriptEntry] } a stream of deliveryNum and transcript entries */ - function* getTranscript(startPos) { - for (const entry of transcriptStore.readSpan(vatID, startPos)) { - yield /** @type { TranscriptEntry } */ (JSON.parse(entry)); + function* getTranscript() { + const bounds = transcriptStore.getCurrentSpanBounds(vatID); + let deliveryNum = bounds.startPos; + // readSpan() starts at startPos and ends just before endPos + for (const entry of transcriptStore.readSpan(vatID)) { + const te = /** @type { TranscriptEntry } */ (JSON.parse(entry)); + /** @type { [number, TranscriptEntry]} */ + const retval = [deliveryNum, te]; + yield retval; + deliveryNum += 1; } } @@ -506,34 +520,55 @@ export function makeVatKeeper( * Store a snapshot, if given a snapStore. * * @param {VatManager} manager - * @returns {Promise} + * @returns {Promise} */ async function saveSnapshot(manager) { if (!snapStore || !manager.makeSnapshot) { - return false; + return; } + // tell the manager to save a heap snapshot to the snapStore const endPosition = getTranscriptEndPosition(); const info = await manager.makeSnapshot(endPosition, snapStore); - transcriptStore.rolloverSpan(vatID); + const { - hash, + hash: snapshotID, uncompressedSize, rawSaveSeconds, compressedSize, compressSeconds, } = info; + + // push a save-snapshot transcript entry + addToTranscript({ + d: /** @type {TDSaveSnapshot} */ ['save-snapshot'], + sc: [], + r: { status: 'ok', snapshotID }, + }); + + // then start a new transcript span + transcriptStore.rolloverSpan(vatID); + + // then push a load-snapshot entry, so that the current span + // always starts with an initialize-worker or load-snapshot + // pseudo-delivery + const loadConfig = { snapshotID }; + addToTranscript({ + d: /** @type {TDLoadSnapshot} */ ['load-snapshot', loadConfig], + sc: [], + r: { status: 'ok' }, + }); + kernelSlog.write({ type: 'heap-snapshot-save', vatID, - hash, + snapshotID, uncompressedSize, rawSaveSeconds, compressedSize, compressSeconds, endPosition, }); - return true; } function deleteSnapshotsAndTranscript() { @@ -611,6 +646,7 @@ export function makeVatKeeper( hasCListEntry, deleteCListEntry, deleteCListEntriesForKernelSlots, + transcriptSize, getTranscript, transcriptSnapshotStats, addToTranscript, diff --git a/packages/SwingSet/src/kernel/vat-warehouse.js b/packages/SwingSet/src/kernel/vat-warehouse.js index 1b53df8e11db..27cadbf4804d 100644 --- a/packages/SwingSet/src/kernel/vat-warehouse.js +++ b/packages/SwingSet/src/kernel/vat-warehouse.js @@ -11,6 +11,10 @@ import djson from '../lib/djson.js'; * @typedef {import('@agoric/swingset-liveslots').VatSyscallResult} VatSyscallResult * @typedef {import('@agoric/swingset-liveslots').VatSyscallHandler} VatSyscallHandler * @typedef {import('../types-internal.js').VatManager} VatManager + * @typedef {import('../types-internal.js').VatID} VatID + * @typedef {import('../types-internal.js').TranscriptDeliveryInitializeWorkerOptions} TDInitializeWorkerOptions + * @typedef {import('../types-internal.js').TranscriptDeliveryInitializeWorker} TDInitializeWorker + * @typedef {import('../types-internal.js').TranscriptDeliveryShutdownWorker} TDShutdownWorker * @typedef {import('../types-internal.js').TranscriptDeliveryResults} TranscriptDeliveryResults * @typedef {import('../types-internal.js').TranscriptEntry} TranscriptEntry * @typedef {{ body: string, slots: unknown[] }} Capdata @@ -38,8 +42,31 @@ function recordSyscalls(origHandler) { syscalls.push({ s: vso, r: vres }); return vres; }; - const getTranscriptSyscalls = () => syscalls; - return { syscallHandler, getTranscriptSyscalls }; + const getTranscriptEntry = (vd, deliveryResult) => { + // TODO add metering computrons to results + /** @type {TranscriptDeliveryResults} */ + const tdr = { status: deliveryResult[0] }; + const transcriptEntry = { d: vd, sc: syscalls, r: tdr }; + return transcriptEntry; + }; + return { syscallHandler, getTranscriptEntry }; +} + +/** + * @param {TranscriptEntry} transcriptEntry + * @returns {VatDeliveryObject} + */ +function onlyRealDelivery(transcriptEntry) { + const dtype = transcriptEntry.d[0]; + if ( + dtype === 'save-snapshot' || + dtype === 'load-snapshot' || + dtype === 'initialize-worker' || + dtype === 'shutdown-worker' + ) { + throw Fail`replay should not see ${dtype}`; + } + return transcriptEntry.d; } /** @@ -253,28 +280,33 @@ export function makeVatWarehouse({ * @returns {Promise} */ async function replayTranscript(vatID, vatKeeper, manager) { - const snapshotInfo = vatKeeper.getSnapshotInfo(); - const startPos = snapshotInfo ? snapshotInfo.endPos : undefined; - // console.log('replay from', { vatID, startPos }); - - const total = vatKeeper.vatStats().transcriptCount; + const total = vatKeeper.transcriptSize(); kernelSlog.write({ type: 'start-replay', vatID, deliveries: total }); - // TODO glean deliveryNum better, make sure we get the post-snapshot - // transcript starting point right. getTranscript() should probably - // return [deliveryNum, t] pairs. - let deliveryNum = startPos || 0; - for await (const te of vatKeeper.getTranscript(startPos)) { + let first = true; + for await (const [deliveryNum, te] of vatKeeper.getTranscript()) { // if (deliveryNum % 100 === 0) { // console.debug(`replay vatID:${vatID} deliveryNum:${deliveryNum} / ${total}`); // } // + if (first) { + // the first entry should always be initialize-worker or + // load-snapshot + first = false; + const dtype = te.d[0]; + if (dtype === 'initialize-worker' || dtype === 'load-snapshot') { + continue; // TODO: use this to launch the worker + } else { + console.error(`transcript for ${vatID} starts with ${te.d[0]}`); + throw Fail`transcript for ${vatID} doesn't start with init/load`; + } + } // we slog the replay just like the original, but some fields are missing const finishSlog = slogReplay(kernelSlog, vatID, deliveryNum, te); + const delivery = onlyRealDelivery(te); const sim = makeSyscallSimulator(kernelSlog, vatID, deliveryNum, te); - const status = await manager.deliver(te.d, sim.syscallHandler); + const status = await manager.deliver(delivery, sim.syscallHandler); finishSlog(status); sim.finishSimulation(); // will throw if syscalls did not match - deliveryNum += 1; } kernelSlog.write({ type: 'finish-replay', vatID }); } @@ -298,6 +330,22 @@ export function makeVatWarehouse({ const translators = provideTranslators(vatID); const syscallHandler = buildVatSyscallHandler(vatID, translators); + // if we use transcripts, but don't have one, create one with an + // initialize-worker event, to represent the vatLoader.create() + // we're about to do + if (options.useTranscript && vatKeeper.transcriptSize() === 0) { + /** @type { TDInitializeWorkerOptions } */ + const initOpts = { source: {}, workerOptions: options.workerOptions }; + // if the vat is somehow using a full bundle, we don't want that + // in the transcript: we only record bundleIDs + initOpts.source.bundleID = source.bundleID; + vatKeeper.addToTranscript({ + d: /** @type {TDInitializeWorker} */ ['initialize-worker', initOpts], + sc: [], + r: { status: 'ok' }, + }); + } + const isDynamic = kernelKeeper.getDynamicVats().includes(vatID); const managerP = vatLoader.create(vatID, { isDynamic, @@ -439,7 +487,7 @@ export function makeVatWarehouse({ * options: pay $/block to keep in RAM - advisory; not consensus * creation arg: # of vats to keep in RAM (LRU 10~50~100) * - * @param {string} currentVatID + * @param {VatID} currentVatID */ async function applyAvailabilityPolicy(currentVatID) { const lru = recent.add(currentVatID); @@ -453,13 +501,9 @@ export function makeVatWarehouse({ await evict(lru); } - /** @type { string | undefined } */ - let lastVatID; - /** @type {(vatID: string, kd: KernelDeliveryObject, d: VatDeliveryObject, vs: VatSlog) => Promise } */ async function deliverToVat(vatID, kd, vd, vs) { await applyAvailabilityPolicy(vatID); - lastVatID = vatID; const recreate = true; // PANIC in the failure case // create the worker and replay the transcript, if necessary @@ -479,7 +523,7 @@ export function makeVatWarehouse({ // wrap the syscallHandler with a syscall recorder const recorder = recordSyscalls(origHandler); - const { syscallHandler, getTranscriptSyscalls } = recorder; + const { syscallHandler, getTranscriptEntry } = recorder; assert(syscallHandler); // make the delivery @@ -490,11 +534,7 @@ export function makeVatWarehouse({ // TODO: if the dispatch failed for whatever reason, and we choose to // destroy the vat, change what we do with the transcript here. if (options.useTranscript) { - // record transcript entry - /** @type {TranscriptDeliveryResults} */ - const tdr = { status: deliveryResult[0] }; - const transcriptEntry = { d: vd, sc: getTranscriptSyscalls(), r: tdr }; - vatKeeper.addToTranscript(transcriptEntry); + vatKeeper.addToTranscript(getTranscriptEntry(vd, deliveryResult)); } // TODO: if per-vat policy decides it wants a BOYD or heap snapshot, @@ -504,21 +544,19 @@ export function makeVatWarehouse({ } /** - * Save a snapshot of most recently used vat, - * depending on snapshotInterval. + * Save a heap snapshot for the given vatID, if the snapshotInterval + * is satisified + * + * @param {VatID} vatID */ - async function maybeSaveSnapshot() { - if (!lastVatID || !lookup(lastVatID)) { - return false; - } - + async function maybeSaveSnapshot(vatID) { const recreate = true; // PANIC in the failure case - const { manager } = await ensureVatOnline(lastVatID, recreate); + const { manager } = await ensureVatOnline(vatID, recreate); if (!manager.makeSnapshot) { - return false; + return false; // worker cannot make snapshots } - const vatKeeper = kernelKeeper.provideVatKeeper(lastVatID); + const vatKeeper = kernelKeeper.provideVatKeeper(vatID); let reason; const { totalEntries, snapshottedEntries } = vatKeeper.transcriptSnapshotStats(); @@ -532,10 +570,15 @@ export function makeVatWarehouse({ } // console.log('maybeSaveSnapshot: reason:', reason); if (!reason) { - return false; + return false; // not time to make a snapshot } + + // in addition to saving the actual snapshot, + // vatKeeper.saveSnapshot() pushes a save-snapshot transcript + // entry, then starts a new transcript span, then pushes a + // load-snapshot entry, so that the current span always starts + // with an initialize-snapshot or load-snapshot pseudo-delivery await vatKeeper.saveSnapshot(manager); - lastVatID = undefined; return true; } @@ -584,6 +627,11 @@ export function makeVatWarehouse({ async function beginNewWorkerIncarnation(vatID) { await evict(vatID); const vatKeeper = kernelKeeper.provideVatKeeper(vatID); + vatKeeper.addToTranscript({ + d: /** @type {TDShutdownWorker} */ ['shutdown-worker'], + sc: [], + r: { status: 'ok' }, + }); return vatKeeper.beginNewIncarnation(); } diff --git a/packages/SwingSet/src/types-internal.js b/packages/SwingSet/src/types-internal.js index 5b4d40892bc3..6aa92251f2cd 100644 --- a/packages/SwingSet/src/types-internal.js +++ b/packages/SwingSet/src/types-internal.js @@ -98,7 +98,22 @@ export {}; */ /** + * @typedef { { source: { bundleID?: BundleID }, workerOptions: WorkerOptions } } TranscriptDeliveryInitializeWorkerOptions + * @typedef { [tag: 'initialize-worker', options: TranscriptDeliveryInitializeWorkerOptions] } TranscriptDeliveryInitializeWorker + * @typedef { [tag: 'save-snapshot'] } TranscriptDeliverySaveSnapshot + * @typedef { { snapshotID: string } } TranscriptDeliverySnapshotConfig + * @typedef { [tag: 'load-snapshot', config: TranscriptDeliverySnapshotConfig] } TranscriptDeliveryLoadSnapshot + * @typedef { [tag: 'shutdown-worker'] } TranscriptDeliveryShutdownWorker + * @typedef { VatDeliveryObject + * | TranscriptDeliveryInitializeWorker + * | TranscriptDeliverySaveSnapshot + * | TranscriptDeliveryLoadSnapshot + * | TranscriptDeliveryShutdownWorker + * } TranscriptDelivery * @typedef { { s: VatSyscallObject, r: VatSyscallResult } } TranscriptSyscall - * @typedef { { status: string } } TranscriptDeliveryResults - * @typedef { { d: VatDeliveryObject, sc: TranscriptSyscall[], r: TranscriptDeliveryResults } } TranscriptEntry + * @typedef { { status: string, snapshotID: string } } TranscriptDeliverySaveSnapshotResults + * @typedef { { status: string } } TranscriptDeliveryGenericResults + * @typedef { TranscriptDeliverySaveSnapshotResults | TranscriptDeliveryGenericResults } TranscriptDeliveryResults + * @typedef { { d: TranscriptDelivery, sc: TranscriptSyscall[], r: TranscriptDeliveryResults } } TranscriptEntry + * */ diff --git a/packages/SwingSet/test/test-controller.js b/packages/SwingSet/test/test-controller.js index d9d37cfa35a2..1e66bdb3e00a 100644 --- a/packages/SwingSet/test/test-controller.js +++ b/packages/SwingSet/test/test-controller.js @@ -35,6 +35,7 @@ test('load empty', async t => { async function simpleCall(t) { const config = { + defaultManagerType: 'local', vats: { vat1: { sourceSpec: new URL('vat-controller-1.js', import.meta.url).pathname, @@ -55,12 +56,37 @@ async function simpleCall(t) { const vattpVatID = controller.vatNameToID('vattp'); const timerVatID = controller.vatNameToID('timer'); + // snoop the bundleID to use + const stateFor = vatID => { + const source = JSON.parse(kernelStorage.kvStore.get(`${vatID}.source`)); + const { bundleID } = source; + const transcript = [ + [ + 0, + { + d: [ + 'initialize-worker', + { + source: { bundleID }, + workerOptions: { + type: 'local', + }, + }, + ], + sc: [], + r: { status: 'ok' }, + }, + ], + ]; + const state = { transcript }; + return { vatID, state }; + }; t.deepEqual(data.vatTables, [ - { vatID: adminVatID, state: { transcript: [] } }, - { vatID: commsVatID, state: { transcript: [] } }, - { vatID: vattpVatID, state: { transcript: [] } }, - { vatID: timerVatID, state: { transcript: [] } }, - { vatID: vat1ID, state: { transcript: [] } }, + stateFor(adminVatID), + { vatID: commsVatID, state: { transcript: [] } }, // transcriptless + stateFor(vattpVatID), + stateFor(timerVatID), + stateFor(vat1ID), ]); // the vatAdmin root is pre-registered const vatAdminRoot = ['ko20', adminVatID, 'o+0']; diff --git a/packages/SwingSet/test/test-kernel.js b/packages/SwingSet/test/test-kernel.js index 9bd2ee4b83e4..92cfbc601a3b 100644 --- a/packages/SwingSet/test/test-kernel.js +++ b/packages/SwingSet/test/test-kernel.js @@ -38,7 +38,7 @@ async function makeKernel() { return buildKernel(endowments, {}, {}); } -const tsv = [{ d: ['startVat', kser({})], sc: [], r: { status: 'ok' } }]; +const tsv = [[0, { d: ['startVat', kser({})], sc: [], r: { status: 'ok' } }]]; test('build kernel', async t => { const kernel = await makeKernel(); @@ -150,7 +150,7 @@ test('vat store', async t => { ]); const data = kernel.dump(); // check that we're not sticking an undefined into the transcript - t.deepEqual(data.vatTables[0].state.transcript[1].sc[0].r, ['ok', null]); + t.deepEqual(data.vatTables[0].state.transcript[1][1].sc[0].r, ['ok', null]); }); test('map inbound', async t => { @@ -1171,27 +1171,30 @@ test('transcript', async t => { const tr = kernel.dump().vatTables[0].state.transcript; t.is(tr.length, 2); t.deepEqual(tr[0], tsv[0]); - t.deepEqual(tr[1], { - d: [ - 'message', - aliceForAlice, - { - methargs: kser(['store', [kslot(aliceForAlice), kslot(bobForAlice)]]), - result: 'p-60', - }, - ], - sc: [ - { - s: [ - 'send', - bobForAlice, - { methargs: kser(['foo', ['fooarg']]), result: 'p+5' }, - ], - r: ['ok', null], - }, - ], - r: { status: 'ok' }, - }); + t.deepEqual(tr[1], [ + 1, + { + d: [ + 'message', + aliceForAlice, + { + methargs: kser(['store', [kslot(aliceForAlice), kslot(bobForAlice)]]), + result: 'p-60', + }, + ], + sc: [ + { + s: [ + 'send', + bobForAlice, + { methargs: kser(['foo', ['fooarg']]), result: 'p+5' }, + ], + r: ['ok', null], + }, + ], + r: { status: 'ok' }, + }, + ]); }); // p1=x!foo(); p2=p1!bar(); p3=p2!urgh(); no pipelining. p1 will have a diff --git a/packages/SwingSet/test/transcript/test-transcript-entries.js b/packages/SwingSet/test/transcript/test-transcript-entries.js new file mode 100644 index 000000000000..593affa647f7 --- /dev/null +++ b/packages/SwingSet/test/transcript/test-transcript-entries.js @@ -0,0 +1,317 @@ +import test from 'ava'; +import '@endo/init/debug.js'; +import { initSwingStore } from '@agoric/swing-store'; +import { initializeSwingset, makeSwingsetController } from '../../src/index.js'; +import { buildKernelBundle } from '../../src/controller/initializeSwingset.js'; +import { kunser } from '../../src/lib/kmarshal.js'; + +const bfile = name => new URL(name, import.meta.url).pathname; + +test.before(async t => { + const runtimeOptions = { kernelBundle: await buildKernelBundle() }; + t.context.data = { runtimeOptions }; +}); + +test('transcript of new vats', async t => { + const config = { + bootstrap: 'static1', + defaultReapInterval: 'never', + snapshotInitial: 1000, // effectively disable + snapshotInterval: 1000, // same + bundles: { + bundle: { sourceSpec: bfile('vat-bootstrap-transcript.js') }, + }, + vats: { + static1: { bundleName: 'bundle' }, + static2: { bundleName: 'bundle' }, + }, + }; + const kernelStorage = initSwingStore().kernelStorage; + const { kvStore, transcriptStore } = kernelStorage; + const { readSpan } = transcriptStore; + await initializeSwingset(config, [], kernelStorage); + const c = await makeSwingsetController(kernelStorage); + t.teardown(c.shutdown); + + const vatID1 = c.vatNameToID('static1'); + const vatID2 = c.vatNameToID('static2'); + + // vat preload should cause all our static vats to have a transcript + let t1 = [...readSpan(vatID1, 0)].map(JSON.parse); + let t2 = [...readSpan(vatID2, 0)].map(JSON.parse); + t.deepEqual( + t1.map(te => te.d[0]), + ['initialize-worker'], + ); + t.deepEqual( + t2.map(te => te.d[0]), + ['initialize-worker'], + ); + + // the first run will perform the 'startVat' deliveries to all vats, + // and the bootstrap message (which does createVatAdminService) + await c.run(); + t1 = [...readSpan(vatID1, 0)].map(JSON.parse); + t2 = [...readSpan(vatID2, 0)].map(JSON.parse); + + t.deepEqual( + t1.map(te => te.d[0]), + [ + 'initialize-worker', + 'startVat', + 'message', // bootstrap + 'dropExports', // nobody else is using bootstrap root + 'retireExports', + 'notify', + ], + ); + t.deepEqual( + t2.map(te => te.d[0]), + ['initialize-worker', 'startVat'], + ); + + const kpid = c.queueToVatRoot('static1', 'create', [], 'panic'); + await c.run(); + t.is(c.kpStatus(kpid), 'fulfilled'); + const dynRootKref = kunser(c.kpResolution(kpid)).getKref(); // usually ko28 + + // we snoop the kernel object table to find the new vatID + const dynVatID = kvStore.get(`${dynRootKref}.owner`); // usually v7 + const t3 = [...readSpan(dynVatID, 0)].map(JSON.parse); + + t.deepEqual( + t3.map(te => te.d[0]), + ['initialize-worker', 'startVat'], + ); +}); + +test('transcript spans', async t => { + const config = { + snapshotInitial: 2, + // the new pseudo-deliveries ('initialize-worker', + // 'save-snapshot', and 'load-snapshot' all count against the + // snapshotInterval. So setting it to 7 will get us 5 actual + // deliveries between the two snapshot events. + snapshotInterval: 7, + defaultReapInterval: 'never', + defaultManagerType: 'xsnap', + bundles: { + bundle: { sourceSpec: bfile('vat-bootstrap-transcript.js') }, + }, + vats: { + bootstrap: { bundleName: 'bundle' }, + }, + bootstrap: 'bootstrap', + }; + const { kernelStorage, internal, hostStorage } = initSwingStore(); + const { transcriptStore, snapStore } = internal; + const { commit } = hostStorage; + const initOpts = { addComms: false, addVattp: false, addTimer: false }; + await initializeSwingset(config, [], kernelStorage, initOpts); + commit(); + + let c; + const restart = async () => { + if (c) { + commit(); + await c.shutdown(); + } + const { runtimeOptions } = t.context.data; + c = await makeSwingsetController(kernelStorage, {}, runtimeOptions); + t.teardown(c.shutdown); + return c; + }; + + c = await restart(); // actually just starting for the first time + let expectedFull = ['initialize-worker']; + c.pinVatRoot('bootstrap'); + const vatID = c.vatNameToID('bootstrap'); + + const snapInfo = () => snapStore.getSnapshotInfo(vatID)?.endPos; + const readFull = () => [...transcriptStore.readFullVatTranscript(vatID)]; + const full = () => readFull().map(row => JSON.parse(row.item)); + const readOld = startPos => [...transcriptStore.readSpan(vatID, startPos)]; + const old = startPos => readOld(startPos).map(item => JSON.parse(item)); + const readCur = () => [...transcriptStore.readSpan(vatID)]; + const cur = () => readCur().map(item => JSON.parse(item)); + const summarize = te => te.d[0]; + const fullSummary = () => full().map(summarize); + const oldSummary = startPos => old(startPos).map(summarize); + const curSummary = () => cur().map(summarize); + const init = ['initialize-worker']; + const start = ['initialize-worker', 'startVat']; + const boyd = ['bringOutYourDead']; + const shutdown = ['shutdown-worker']; + const save = ['save-snapshot']; + const load = ['load-snapshot']; + const notify = ['notify']; + const snap = [].concat(save, load); + const boot = ['message']; // bootstrap(), not nothing() + const msg = ['message']; // nothing() + const msgN = n => Array(n).fill('message'); + const bounds = () => { + const b = transcriptStore.getCurrentSpanBounds(vatID); + return [b.startPos, b.endPos]; + }; + const incarnation = () => + transcriptStore.getCurrentSpanBounds(vatID)?.incarnation; + + // snapshotInitial=2 and snapshotInterval=7, so we'll see a + // save-snapshot on deliveryNum 2, and when (deliveryNum - + // snapshot.endPos) = k*7. Until an upgrade causes a span to end + // early, that means save-snapshot on deliveries 2, 9, 16, 23 + + // the full sequence of deliveries will be: + // span 0-2 = [0,3) (ended by snapshot) + // 0 initialize-worker + // 1 startVat + // 2 save-snapshot + // span 3-9 = [3, 10) (ended by snapshot) + // 3 load-snapshot + // 4 boot (message: bootstrap()) + // 5 notify (response to createVatAdminService) + // 6 message (nothing-1) + // 7 message (nothing-2) + // 8 message (nothing-3) + // 9 save-snapshot + // span 10-15 = [10, 16) (ended by upgrade) + // 10 load-snapshot + // 11 message (nothing-4) + // 12 message (nothing-5) + // 13 message (nothing-6) + // 14 bringOutYourDead (for upgrade) + // 15 shutdown-worker (for upgrade) + // (span ended, snapshot removed, span started) + // span 16-19 = [16,20) + // 16 initialize-worker (added by ensureVatOnline) + // 17 startVat + // 18 message (nothing-7) + // (now maybeSaveSnapshot notices) + // 19 save-snapshot + // span 20- = [20,..) (still active at end of test) + // 20 load-snapshot + + t.deepEqual(fullSummary(), expectedFull); + t.deepEqual(bounds(), [0, 1]); + t.deepEqual(curSummary(), ['initialize-worker']); + t.is(snapInfo(), undefined); + t.is(incarnation(), 0); + + // restart immediately, to exercise vat-preload seeing just the + // initialize-worker + + c = await restart(); + t.deepEqual(curSummary(), ['initialize-worker']); + t.is(snapInfo(), undefined); + t.is(incarnation(), 0); + + // starting the kernel will deliver the 'startVat' delivery to all + // vats. And since snapshotInitial=2, we'll get an immediate + // snapshot cycle after the 'startVat'. Then 'bootstrap()' and the + // notify from createVatAdminService are delivered + await c.run(); + expectedFull = expectedFull.concat('startVat', snap, boot, notify); + // first span is 0-2 = [0,3), snapshot happened on the last event + // "2". current span is 3-5 = [3,6) + t.is(snapInfo(), 2); + t.is(incarnation(), 0); + t.deepEqual(bounds(), [3, 6]); + t.deepEqual(oldSummary(0), [].concat(start, save)); + t.deepEqual(curSummary(), [].concat(load, boot, notify)); + t.deepEqual(fullSummary(), expectedFull); + + // do some deliveries to trigger an XS heap snapshot event, creating + // a new span + const doSomeNothing = async () => { + const kpid = c.queueToVatRoot('bootstrap', 'nothing', [], 'panic'); + await c.run(); + t.is(c.kpStatus(kpid), 'fulfilled'); + }; + + await doSomeNothing(); // d6: nothing-1 + expectedFull = expectedFull.concat(msg); + t.is(snapInfo(), 2); + t.is(incarnation(), 0); + t.deepEqual(bounds(), [3, 7]); + t.deepEqual(curSummary(), [].concat(load, boot, notify, msgN(1))); + t.deepEqual(fullSummary(), expectedFull); + + c = await restart(); + t.deepEqual(curSummary(), [].concat(load, boot, notify, msgN(1))); + + await doSomeNothing(); // d7: nothing-2 + expectedFull = expectedFull.concat(msg); + t.deepEqual(curSummary(), [].concat(load, boot, notify, msgN(2))); + await doSomeNothing(); // d8: nothing-3 + expectedFull = expectedFull.concat(msg); + // 8th delivery hits snapshotInterval, so we get a save/load + // cycle. Spans are [0,3), [3,10), [10,11). There were snapshots on + // 2 and 9. + expectedFull = expectedFull.concat(snap); + t.is(snapInfo(), 9); + t.is(incarnation(), 0); + t.deepEqual(bounds(), [10, 11]); + t.deepEqual(curSummary(), [].concat(load)); + t.deepEqual(fullSummary(), expectedFull); + c = await restart(); + t.deepEqual(curSummary(), [].concat(load)); + + await doSomeNothing(); // nothing-4 + expectedFull = expectedFull.concat(msg); + t.is(snapInfo(), 9); + t.is(incarnation(), 0); + t.deepEqual(bounds(), [10, 12]); + t.deepEqual(oldSummary(3), [].concat(load, boot, notify, msgN(3), save)); + t.deepEqual(curSummary(), [].concat(load, msg)); + t.deepEqual(fullSummary(), expectedFull); + + c = await restart(); + t.deepEqual(curSummary(), [].concat(load, msg)); + + // two more for good measure + await doSomeNothing(); // nothing-5 + expectedFull = expectedFull.concat(msg); + await doSomeNothing(); // nothing-6 + expectedFull = expectedFull.concat(msg); + t.is(snapInfo(), 9); + t.is(incarnation(), 0); + t.deepEqual(bounds(), [10, 14]); + t.deepEqual(curSummary(), [].concat(load, msgN(3))); + t.deepEqual(fullSummary(), expectedFull); + + // Now upgrade the vat, introducing a new incarnation. We do a null + // upgrade, but need to snoop the bundleID to use. + const source = JSON.parse(kernelStorage.kvStore.get(`${vatID}.source`)); + const { bundleID } = source; + c.upgradeStaticVat('bootstrap', false, bundleID); + expectedFull = expectedFull.concat(boyd, shutdown, start); + await c.run(); + // a weirdness in the way maybeSaveSnapshot counts means that after + // an upgrade, we'll do a snapshot immediately after the first + // message delivery (because processDeliveryMessage calls + // maybeSaveSnapshot), but not after the startVat done by + // processUpgradeVat + t.is(snapInfo(), undefined); + t.is(incarnation(), 1); + t.deepEqual(oldSummary(10), [].concat(load, msgN(3), boyd, shutdown)); + t.deepEqual(bounds(), [16, 18]); + t.deepEqual(curSummary(), [].concat(start)); + t.deepEqual(fullSummary(), expectedFull); + + // restarting at this point means we load a blank worker and replay + // startVat, since we haven't created a snapshot yet + c = await restart(); + t.is(snapInfo(), undefined); + t.is(incarnation(), 1); + t.deepEqual(curSummary(), [].concat(start)); + + // so this provokes a snapshot, leaving us in an empty span + await doSomeNothing(); // nothing-7 + expectedFull = expectedFull.concat(msg, snap); + t.is(snapInfo(), 19); + t.is(incarnation(), 1); + t.deepEqual(bounds(), [20, 21]); + t.deepEqual(oldSummary(16), [].concat(init, ['startVat'], msg, save)); + t.deepEqual(curSummary(), [].concat(load)); + t.deepEqual(fullSummary(), expectedFull); +}); diff --git a/packages/SwingSet/test/transcript/vat-bootstrap-transcript.js b/packages/SwingSet/test/transcript/vat-bootstrap-transcript.js new file mode 100644 index 000000000000..b4dcd15184bf --- /dev/null +++ b/packages/SwingSet/test/transcript/vat-bootstrap-transcript.js @@ -0,0 +1,15 @@ +import { E, Far } from '@endo/far'; + +export const buildRootObject = harden(() => { + let vas; + return Far('root', { + bootstrap: async (vats, devices) => { + vas = await E(vats.vatAdmin).createVatAdminService(devices.vatAdmin); + }, + create: async () => { + const { root } = await E(vas).createVatByName('bundle'); + return root; + }, + nothing: () => {}, + }); +}); diff --git a/packages/SwingSet/test/vat-warehouse/test-reload-snapshot.js b/packages/SwingSet/test/vat-warehouse/test-reload-snapshot.js index 2dae19bbca33..5e4bdb15dcbc 100644 --- a/packages/SwingSet/test/vat-warehouse/test-reload-snapshot.js +++ b/packages/SwingSet/test/vat-warehouse/test-reload-snapshot.js @@ -37,35 +37,64 @@ test('vat reload from snapshot', async t => { function getPositions() { const snapshotInfo = snapStore.getSnapshotInfo(vatID); - const start = snapshotInfo ? snapshotInfo.endPos : 0; + const snap = snapshotInfo ? snapshotInfo.endPos : 0; const bounds = kernelStorage.transcriptStore.getCurrentSpanBounds(vatID); + const start = bounds.startPos; const end = bounds.endPos; - return [start, end]; + return [snap, start, end]; } + // the deliveries to vat-target are: + // * 0: initialize-worker + // * 1: startVat const expected1 = []; c1.queueToVatRoot('target', 'count', []); + // * 2: message (count=0) + // * then we hit snapshotInitial + // * 3: save-snapshot + // * 4: load-snapshot expected1.push(`count = 0`); await c1.run(); t.deepEqual(c1.dump().log, expected1); - t.deepEqual(getPositions(), [0, 2]); + t.deepEqual(getPositions(), [3, 4, 5]); for (let i = 1; i < 11; i += 1) { c1.queueToVatRoot('target', 'count', []); + // * 5: message (count=1) + // * 6: message (count=2) + // * 7: message (count=3) + // * then we hit snapshotInterval + // * 8: save-snapshot + // * 9: load-snapshot + // * 10: message (count=4) + // * 11: message (count=5) + // * 12: message (count=6) + // * then we hit snapshotInterval + // * 13: save-snapshot + // * 14: load-snapshot + // * 15: message (count=7) + // * 16: message (count=8) + // * 17: message (count=9) + // * then we hit snapshotInterval + // * 18: save-snapshot + // * 19: load-snapshot + // * 20: message (count=10) expected1.push(`count = ${i}`); } await c1.run(); t.deepEqual(c1.dump().log, expected1); - t.deepEqual(getPositions(), [8, 12]); + t.deepEqual(getPositions(), [18, 19, 21]); await c1.shutdown(); + // the worker will start with the load-snapshot at d19, and replay d20 const c2 = await makeSwingsetController(kernelStorage); - const expected2 = [`count = 7`, `count = 8`, `count = 9`, `count = 10`]; + const expected2 = [`count = 10`]; t.deepEqual(c2.dump().log, expected2); // replayed 4 deliveries c2.queueToVatRoot('target', 'count', []); + // * 21: message(count=11) expected2.push(`count = 11`); await c2.run(); t.deepEqual(c2.dump().log, expected2); // note: *not* 0-11 - t.deepEqual(getPositions(), [13, 13]); + t.deepEqual(getPositions(), [18, 19, 22]); await c2.shutdown(); }); diff --git a/packages/SwingSet/test/xsnap-stable-bundles/test-stable-bundles.js b/packages/SwingSet/test/xsnap-stable-bundles/test-stable-bundles.js index 738e65fff648..b3c9d64da5d8 100644 --- a/packages/SwingSet/test/xsnap-stable-bundles/test-stable-bundles.js +++ b/packages/SwingSet/test/xsnap-stable-bundles/test-stable-bundles.js @@ -87,7 +87,7 @@ test('xsnap bundles are stable', async t => { const config = { includeDevDependencies: true, // for @endo/far defaultManagerType: 'local', - snapshotInitial: 1, + snapshotInitial: 2, bootstrap: 'bootstrap', bundles: { bootstrap: { @@ -168,11 +168,16 @@ test('xsnap bundles are stable', async t => { t.deepEqual(log, preloadV1); log.length = 0; - // now allow the bootstrap message to be delivered, which should - // trigger a snapshot + // the preload pushes an initialize-worker to the transcript, which + // counts as the first delivery (deliveryNum=0), towards our + // snapshotInitial: 2 + + // now allow the bootstrap message to be delivered as deliveryNum=1, + // which should trigger a snapshot, which is recorded in a + // save-snapshot as deliveryNum=2 t.is(snapStore.getSnapshotInfo('v1'), undefined); await c2.run(); - t.is(snapStore.getSnapshotInfo('v1')?.endPos, 1); + t.is(snapStore.getSnapshotInfo('v1')?.endPos, 2); await c2.shutdown; // now that the worker has a snapshot, the vat preload won't fetch