diff --git a/apps/backend/scripts/bulldozer-payments-init.ts b/apps/backend/scripts/bulldozer-payments-init.ts index 6be12197e..5d64a7569 100644 --- a/apps/backend/scripts/bulldozer-payments-init.ts +++ b/apps/backend/scripts/bulldozer-payments-init.ts @@ -34,7 +34,12 @@ import { globalPrismaClient } from "@/prisma-client"; import { throwErr } from "@hexclave/shared/dist/utils/errors"; import { wait } from "@hexclave/shared/dist/utils/promises"; -const BATCH_SIZE = 500; +const DEFAULT_BATCH_SIZE = 50; +type PrismaReplica = ReturnType; +type SubscriptionBackfillRow = Parameters[0][number]; +type SubscriptionInvoiceBackfillRow = Parameters[0][number]; +type OneTimePurchaseBackfillRow = Parameters[0][number]; +type ItemQuantityChangeBackfillRow = Parameters[0][number]; // Fixed processing order. Resume positions are interpreted against this list. export const BACKFILL_TABLES = [ @@ -55,6 +60,11 @@ export type BackfillResumeOptions = { // full list. Lets a single poison row not block a large migration, without // silently dropping it. Default (false) is fail-fast on the first bad row. continueOnError?: boolean, + // Number of rows to page per keyset query and per bulldozer-js batch POST. + // Larger values reduce round-trips but increase per-batch memory/latency and + // the amount of work redone if a batch fails mid-run. Defaults to + // DEFAULT_BATCH_SIZE when omitted. + batchSize?: number, }; /** A row bulldozer-js refused, captured under --continue-on-error. */ @@ -64,12 +74,20 @@ type BackfillFailure = { table: BackfillTableName, tenancyId: string, id: string type BackfillRunContext = { continueOnError: boolean, recordFailure: (failure: BackfillFailure) => void, + batchSize: number, }; function log(message: string) { console.log(`[BulldozerBackfill] ${message}`); } +function formatDuration(ms: number): string { + if (ms < 1000) { + return `${Math.round(ms)}ms`; + } + return `${(ms / 1000).toFixed(1)}s`; +} + function lowerCustomerType(customerType: string): CustomerType { const lowered = customerType.toLowerCase(); if (lowered === "user" || lowered === "team" || lowered === "custom") { @@ -190,12 +208,24 @@ async function backfillTable( let batchNumber = 0; let total = 0; let failed = 0; + // Aggregate the bulldozer request time (the write/POST phase) across the whole + // table so we can report an average per batch at the end — this is the number + // we care about in a backfill load test (the Prisma fetch is local + cheap). + let totalReqMs = 0; + const tableStartedAt = performance.now(); log(`[${label}] starting${cursor ? ` from cursor ${cursor.tenancyId},${cursor.id}` : ""}`); for (;;) { + const fetchStartedAt = performance.now(); const batch = await fetchBatch(cursor); + const fetchMs = performance.now() - fetchStartedAt; if (batch.length === 0) break; + const fetchDoneAt = performance.now(); + // Time only the bulldozer write (the HTTP batch request[s]), isolated from + // the Prisma read above. Under --continue-on-error the per-row retry writes + // are part of the same request phase, so they're included here on purpose. + const reqStartedAt = performance.now(); try { await writeBatch(batch); } catch (error) { @@ -215,7 +245,10 @@ async function backfillTable( } } } + const reqMs = performance.now() - reqStartedAt; + totalReqMs += reqMs; total += batch.length; + const writeDoneAt = performance.now(); const last = batch[batch.length - 1]; const next: Cursor = { tenancyId: last.tenancyId, id: last.id }; @@ -229,23 +262,184 @@ async function backfillTable( cursor = next; batchNumber++; - log(`[${label}] batch=${batchNumber} rows=${batch.length} total=${total}${failed > 0 ? ` failed=${failed}` : ""} cursor=${cursor.tenancyId},${cursor.id}`); + const allDoneAt = performance.now(); + log(`[${label}] batch=${batchNumber} duration=(r:${formatDuration(fetchMs)} w:${formatDuration(writeDoneAt - fetchDoneAt)} t:${formatDuration(allDoneAt - fetchStartedAt)} rows=${batch.length} total=${total}${failed > 0 ? ` failed=${failed}` : ""} cursor=${cursor.tenancyId},${cursor.id}`); // A short page means we've hit the end; skip the extra empty fetch. - if (batch.length < BATCH_SIZE) break; + if (batch.length < ctx.batchSize) break; } - log(`[${label}] done total=${total}${failed > 0 ? ` failed=${failed}` : ""}`); + const tableElapsedMs = performance.now() - tableStartedAt; + const avgReqMs = batchNumber > 0 ? totalReqMs / batchNumber : 0; + log(`[${label}] done total=${total}${failed > 0 ? ` failed=${failed}` : ""} elapsed=${formatDuration(tableElapsedMs)} bulldozerReqTotal=${formatDuration(totalReqMs)} avgReq/batch=${formatDuration(avgReqMs)}`); } -function keysetArgs(cursor: Cursor | null) { - return { - orderBy: [{ tenancyId: "asc" as const }, { id: "asc" as const }], - take: BATCH_SIZE, - ...(cursor - ? { cursor: { tenancyId_id: { tenancyId: cursor.tenancyId, id: cursor.id } }, skip: 1 } - : {}), - }; +async function fetchSubscriptionBatch(replica: PrismaReplica, cursor: Cursor | null, batchSize: number): Promise { + return cursor === null + ? await replica.$queryRaw` + SELECT + "id", + "tenancyId", + "customerId", + "customerType", + "productId", + "priceId", + "product", + "quantity", + "stripeSubscriptionId", + "status", + "currentPeriodEnd", + "currentPeriodStart", + "cancelAtPeriodEnd", + "canceledAt", + "endedAt", + "refundedAt", + "productRevokedAt", + "creationSource", + "createdAt" + FROM "Subscription" + ORDER BY "tenancyId" ASC, "id" ASC + LIMIT ${batchSize} + ` + : await replica.$queryRaw` + SELECT + "id", + "tenancyId", + "customerId", + "customerType", + "productId", + "priceId", + "product", + "quantity", + "stripeSubscriptionId", + "status", + "currentPeriodEnd", + "currentPeriodStart", + "cancelAtPeriodEnd", + "canceledAt", + "endedAt", + "refundedAt", + "productRevokedAt", + "creationSource", + "createdAt" + FROM "Subscription" + WHERE ("tenancyId", "id") > (${cursor.tenancyId}::uuid, ${cursor.id}::uuid) + ORDER BY "tenancyId" ASC, "id" ASC + LIMIT ${batchSize} + `; +} + +async function fetchSubscriptionInvoiceBatch(replica: PrismaReplica, cursor: Cursor | null, batchSize: number): Promise { + return cursor === null + ? await replica.$queryRaw` + SELECT + "id", + "tenancyId", + "stripeSubscriptionId", + "stripeInvoiceId", + "isSubscriptionCreationInvoice", + "status", + "amountTotal", + "hostedInvoiceUrl", + "createdAt" + FROM "SubscriptionInvoice" + ORDER BY "tenancyId" ASC, "id" ASC + LIMIT ${batchSize} + ` + : await replica.$queryRaw` + SELECT + "id", + "tenancyId", + "stripeSubscriptionId", + "stripeInvoiceId", + "isSubscriptionCreationInvoice", + "status", + "amountTotal", + "hostedInvoiceUrl", + "createdAt" + FROM "SubscriptionInvoice" + WHERE ("tenancyId", "id") > (${cursor.tenancyId}::uuid, ${cursor.id}::uuid) + ORDER BY "tenancyId" ASC, "id" ASC + LIMIT ${batchSize} + `; +} + +async function fetchOneTimePurchaseBatch(replica: PrismaReplica, cursor: Cursor | null, batchSize: number): Promise { + return cursor === null + ? await replica.$queryRaw` + SELECT + "id", + "tenancyId", + "customerId", + "customerType", + "productId", + "priceId", + "product", + "quantity", + "stripePaymentIntentId", + "revokedAt", + "refundedAt", + "creationSource", + "createdAt" + FROM "OneTimePurchase" + ORDER BY "tenancyId" ASC, "id" ASC + LIMIT ${batchSize} + ` + : await replica.$queryRaw` + SELECT + "id", + "tenancyId", + "customerId", + "customerType", + "productId", + "priceId", + "product", + "quantity", + "stripePaymentIntentId", + "revokedAt", + "refundedAt", + "creationSource", + "createdAt" + FROM "OneTimePurchase" + WHERE ("tenancyId", "id") > (${cursor.tenancyId}::uuid, ${cursor.id}::uuid) + ORDER BY "tenancyId" ASC, "id" ASC + LIMIT ${batchSize} + `; +} + +async function fetchItemQuantityChangeBatch(replica: PrismaReplica, cursor: Cursor | null, batchSize: number): Promise { + return cursor === null + ? await replica.$queryRaw` + SELECT + "id", + "tenancyId", + "customerId", + "customerType", + "itemId", + "quantity", + "description", + "expiresAt", + "createdAt" + FROM "ItemQuantityChange" + ORDER BY "tenancyId" ASC, "id" ASC + LIMIT ${batchSize} + ` + : await replica.$queryRaw` + SELECT + "id", + "tenancyId", + "customerId", + "customerType", + "itemId", + "quantity", + "description", + "expiresAt", + "createdAt" + FROM "ItemQuantityChange" + WHERE ("tenancyId", "id") > (${cursor.tenancyId}::uuid, ${cursor.id}::uuid) + ORDER BY "tenancyId" ASC, "id" ASC + LIMIT ${batchSize} + `; } /** Tables before `resumeTable` are treated as already done; the rest run. */ @@ -272,10 +466,30 @@ export function parseBackfillResumeOptions(args: string[]): BackfillResumeOption const continueOnError = args.includes("--continue-on-error"); + // Accept both `--batch-size=500` and the space form `--batch-size 500`. The + // space form arrives as two separate argv tokens, so `readArg` (which only + // matches the `name=` prefix) would miss it and we'd silently fall back to the + // default — a nasty footgun. Read the following token in that case, and fail + // loudly if `--batch-size` is present but has no usable value. + const bareBatchSizeIndex = args.indexOf("--batch-size"); + const batchSizeArg = readArg("batch-size") ?? (bareBatchSizeIndex === -1 ? undefined : args[bareBatchSizeIndex + 1]); + let batchSize: number | undefined = undefined; + if (batchSizeArg !== undefined) { + const parsed = Number(batchSizeArg); + if (!Number.isInteger(parsed) || parsed <= 0) { + throw new Error(`--batch-size must be a positive integer (got "${batchSizeArg}")`); + } + batchSize = parsed; + } else if (bareBatchSizeIndex !== -1) { + throw new Error("--batch-size requires a value, e.g. --batch-size=500 or --batch-size 500"); + } + // Common options that apply regardless of whether a resume cursor was passed. + const base: BackfillResumeOptions = { continueOnError, ...(batchSize !== undefined ? { batchSize } : {}) }; + const resumeTableArg = readArg("resume-table"); const resumeCursorArg = readArg("resume-cursor"); if (resumeTableArg === undefined && resumeCursorArg === undefined) { - return { continueOnError }; + return base; } if (resumeTableArg === undefined) { throw new Error("--resume-cursor requires --resume-table"); @@ -285,7 +499,7 @@ export function parseBackfillResumeOptions(args: string[]): BackfillResumeOption throw new Error(`--resume-table must be one of: ${BACKFILL_TABLES.join(", ")}`); } if (resumeCursorArg === undefined) { - return { resumeTable, continueOnError }; + return { ...base, resumeTable }; } const commaIndex = resumeCursorArg.indexOf(","); const tenancyId = commaIndex === -1 ? "" : resumeCursorArg.slice(0, commaIndex); @@ -293,7 +507,7 @@ export function parseBackfillResumeOptions(args: string[]): BackfillResumeOption if (tenancyId.length === 0 || id.length === 0) { throw new Error("--resume-cursor must be in the form ,"); } - return { resumeTable, resumeCursor: { tenancyId, id }, continueOnError }; + return { ...base, resumeTable, resumeCursor: { tenancyId, id } }; } const MAX_FAILURE_PREVIEW = 50; @@ -313,12 +527,14 @@ function formatBackfillFailures(failures: BackfillFailure[]): string { export async function runBulldozerPaymentsInit(options: BackfillResumeOptions = {}) { const replica = globalPrismaClient.$replica(); - log("Backfilling bulldozer-js from Prisma..."); + const batchSize = options.batchSize ?? DEFAULT_BATCH_SIZE; + const runStartedAt = performance.now(); + log(`Backfilling bulldozer-js from Prisma... (batchSize=${batchSize})`); const tables: BackfillTable[] = [ makeTable( "Subscription", - (cursor) => replica.subscription.findMany(keysetArgs(cursor)), + (cursor) => fetchSubscriptionBatch(replica, cursor, batchSize), async (subs) => { await bulldozerWriteSubscriptions(subs); // Synthesize refund transactions for the refunded rows in this page and @@ -331,12 +547,12 @@ export async function runBulldozerPaymentsInit(options: BackfillResumeOptions = ), makeTable( "SubscriptionInvoice", - (cursor) => replica.subscriptionInvoice.findMany(keysetArgs(cursor)), + (cursor) => fetchSubscriptionInvoiceBatch(replica, cursor, batchSize), (invoices) => bulldozerWriteSubscriptionInvoices(invoices), ), makeTable( "OneTimePurchase", - (cursor) => replica.oneTimePurchase.findMany(keysetArgs(cursor)), + (cursor) => fetchOneTimePurchaseBatch(replica, cursor, batchSize), async (purchases) => { await bulldozerWriteOneTimePurchases(purchases); const refunds = purchases @@ -347,7 +563,7 @@ export async function runBulldozerPaymentsInit(options: BackfillResumeOptions = ), makeTable( "ItemQuantityChange", - (cursor) => replica.itemQuantityChange.findMany(keysetArgs(cursor)), + (cursor) => fetchItemQuantityChangeBatch(replica, cursor, batchSize), (changes) => bulldozerWriteItemQuantityChanges(changes), ), ]; @@ -362,6 +578,7 @@ export async function runBulldozerPaymentsInit(options: BackfillResumeOptions = const ctx: BackfillRunContext = { continueOnError: options.continueOnError ?? false, recordFailure: (failure) => failures.push(failure), + batchSize, }; for (const table of tables) { @@ -369,6 +586,9 @@ export async function runBulldozerPaymentsInit(options: BackfillResumeOptions = await table.run(startCursorFor(table.name, options), ctx); } + const processingElapsedMs = performance.now() - runStartedAt; + log(`All tables processed in ${formatDuration(processingElapsedMs)} (excludes the final ~1.5s tick settle wait below).`); + // Under --continue-on-error we deferred bad rows to here; surface them loudly // so the run is never quietly "complete" with data missing. Re-running after // fixing the offending rows re-converges (writes are idempotent). @@ -383,7 +603,8 @@ export async function runBulldozerPaymentsInit(options: BackfillResumeOptions = // a deterministic tick-to-now endpoint would be the upgrade if it ever bites. await wait(1500); - log("Backfill complete."); + const totalElapsedMs = performance.now() - runStartedAt; + log(`Backfill complete. Total wall time: ${formatDuration(totalElapsedMs)}.`); } import.meta.vitest?.describe("parseBackfillResumeOptions", (test) => { @@ -426,6 +647,52 @@ import.meta.vitest?.describe("parseBackfillResumeOptions", (test) => { .toEqual({ resumeTable: "OneTimePurchase", continueOnError: true }); }); + test("omits batchSize when --batch-size is not passed (defaults later)", ({ expect }) => { + expect(parseBackfillResumeOptions([])).not.toHaveProperty("batchSize"); + }); + + test("parses --batch-size on its own", ({ expect }) => { + expect(parseBackfillResumeOptions(["--batch-size=1000"])) + .toEqual({ continueOnError: false, batchSize: 1000 }); + }); + + test("parses the space form --batch-size 100 (two argv tokens)", ({ expect }) => { + expect(parseBackfillResumeOptions(["--batch-size", "100"])) + .toEqual({ continueOnError: false, batchSize: 100 }); + // ...including after the command token, as it arrives via the CLI. + expect(parseBackfillResumeOptions(["backfill-bulldozer-from-prisma", "--batch-size", "100"])) + .toEqual({ continueOnError: false, batchSize: 100 }); + }); + + test("throws (never silently defaults) when --batch-size has no value", ({ expect }) => { + expect(() => parseBackfillResumeOptions(["--batch-size"])) + .toThrow("--batch-size requires a value"); + // A following flag is not a value → still a positive-integer failure, loud. + expect(() => parseBackfillResumeOptions(["--batch-size", "--continue-on-error"])) + .toThrow("--batch-size must be a positive integer"); + }); + + test("parses --batch-size alongside resume flags", ({ expect }) => { + expect(parseBackfillResumeOptions(["--resume-table=Subscription", "--resume-cursor=ten-1,sub-9", "--batch-size=250"])) + .toEqual({ + resumeTable: "Subscription", + resumeCursor: { tenancyId: "ten-1", id: "sub-9" }, + continueOnError: false, + batchSize: 250, + }); + }); + + test("rejects a non-positive or non-integer --batch-size", ({ expect }) => { + expect(() => parseBackfillResumeOptions(["--batch-size=0"])) + .toThrow("--batch-size must be a positive integer"); + expect(() => parseBackfillResumeOptions(["--batch-size=-5"])) + .toThrow("--batch-size must be a positive integer"); + expect(() => parseBackfillResumeOptions(["--batch-size=abc"])) + .toThrow("--batch-size must be a positive integer"); + expect(() => parseBackfillResumeOptions(["--batch-size=1.5"])) + .toThrow("--batch-size must be a positive integer"); + }); + }); import.meta.vitest?.describe("formatBackfillFailures", (test) => { @@ -482,6 +749,7 @@ import.meta.vitest?.describe("backfillTable continue-on-error", (test) => { await backfillTable("Subscription", null, fetchOnce(), failOnBadBatch(written), { continueOnError: true, recordFailure: (f) => failures.push(f), + batchSize: DEFAULT_BATCH_SIZE, }); expect(written).toEqual(["a", "c"]); expect(failures).toEqual([{ table: "Subscription", tenancyId: "t", id: "bad", message: "nope" }]); @@ -494,6 +762,7 @@ import.meta.vitest?.describe("backfillTable continue-on-error", (test) => { backfillTable("Subscription", null, fetchOnce(), failOnBadBatch(written), { continueOnError: false, recordFailure: (f) => failures.push(f), + batchSize: DEFAULT_BATCH_SIZE, }), ).rejects.toThrow("nope"); // The batch fails atomically before recording any row, so nothing is written. diff --git a/apps/backend/scripts/db-migrations.ts b/apps/backend/scripts/db-migrations.ts index 550808907..4725dcfa3 100644 --- a/apps/backend/scripts/db-migrations.ts +++ b/apps/backend/scripts/db-migrations.ts @@ -192,6 +192,7 @@ Commands: --resume-table= --resume-cursor=, --continue-on-error skips rows bulldozer-js rejects and reports them all at the end (default is fail-fast on the first bad row) + --batch-size= rows per page/POST (default 500) backfill-internal-free-plans Grant the free plan to internal-tenancy teams that have no plan. Run AFTER seed. regen-internal-subscriptions-to-latest Bring every active internal-tenancy subscription up to the latest version of its @@ -246,6 +247,8 @@ const main = async () => { // --resume-table= --resume-cursor=, // Optional --continue-on-error: skip rows bulldozer-js rejects and throw // with the full list at the end instead of aborting on the first one. + // Optional --batch-size=: rows per keyset page / bulldozer-js POST + // (default 500). await runBulldozerPaymentsInit(parseBackfillResumeOptions(args)); break; } diff --git a/apps/bulldozer-js/package.json b/apps/bulldozer-js/package.json index da773e238..39c9242c8 100644 --- a/apps/bulldozer-js/package.json +++ b/apps/bulldozer-js/package.json @@ -5,8 +5,8 @@ "private": true, "type": "module", "scripts": { - "start": "tsx src/index.ts", - "dev": "tsx watch --clear-screen=false src/index.ts", + "start": "tsx --expose-gc src/index.ts", + "dev": "tsx watch --clear-screen=false --expose-gc src/index.ts", "run-bulldozer-studio": "tsx watch --clear-screen=false scripts/run-bulldozer-studio.ts", "profile:performance": "tsx scripts/profile-bulldozer-performance.ts", "test": "vitest run", diff --git a/apps/bulldozer-js/scripts/profile-bulldozer-performance.ts b/apps/bulldozer-js/scripts/profile-bulldozer-performance.ts index 2668cad50..72f7a38e3 100644 --- a/apps/bulldozer-js/scripts/profile-bulldozer-performance.ts +++ b/apps/bulldozer-js/scripts/profile-bulldozer-performance.ts @@ -225,10 +225,10 @@ async function main() { await db.applyRemainingMigrations(); let snapshot = (await db.getSnapshot()).snapshot; for (let i = 0; i < 8; i++) { - snapshot = await snapshot.setOrDeleteRow({ tableId: "prices", rowIdentifier: `asset-${i}`, newRowData: { asset: `asset-${i}`, usd: 100 + i } }); + snapshot = (await snapshot.setOrDeleteRow({ tableId: "prices", rowIdentifier: `asset-${i}`, newRowData: { asset: `asset-${i}`, usd: 100 + i } })).newSnapshot; } for (let i = 0; i < rowCount; i++) { - snapshot = await snapshot.setOrDeleteRow({ tableId: "events", rowIdentifier: `event-${i}`, newRowData: eventRow(i) }); + snapshot = (await snapshot.setOrDeleteRow({ tableId: "events", rowIdentifier: `event-${i}`, newRowData: eventRow(i) })).newSnapshot; } resetMetrics(); @@ -236,11 +236,11 @@ async function main() { const targetIndex = rowCount - 1; for (let iteration = 0; iteration < measuredIterations; iteration++) { const start = performance.now(); - snapshot = await snapshot.setOrDeleteRow({ + snapshot = (await snapshot.setOrDeleteRow({ tableId: "events", rowIdentifier: `event-${targetIndex}`, newRowData: eventRow(targetIndex, rowCount * 10 + iteration), - }); + })).newSnapshot; durations.push(performance.now() - start); } diff --git a/apps/bulldozer-js/src/databases/bulldozer/example-schema.ts b/apps/bulldozer-js/src/databases/bulldozer/example-schema.ts index b25fbd181..4f18128b6 100644 --- a/apps/bulldozer-js/src/databases/bulldozer/example-schema.ts +++ b/apps/bulldozer-js/src/databases/bulldozer/example-schema.ts @@ -348,7 +348,7 @@ export async function createExampleFungibleLedgerDatabase() { await db.applyRemainingMigrations(); await db.withSnapshotReplicated(async snapshot => { for (const [rowIdentifier, rowData] of Object.entries(exampleLedgerRows)) { - snapshot = await snapshot.setOrDeleteRow({ tableId: storedTableId, rowIdentifier, newRowData: rowData as unknown as PiledriverObject }); + snapshot = (await snapshot.setOrDeleteRow({ tableId: storedTableId, rowIdentifier, newRowData: rowData as unknown as PiledriverObject })).newSnapshot; } return snapshot; }); diff --git a/apps/bulldozer-js/src/databases/bulldozer/index.test.ts b/apps/bulldozer-js/src/databases/bulldozer/index.test.ts index a2a51d28c..5cdd3802b 100644 --- a/apps/bulldozer-js/src/databases/bulldozer/index.test.ts +++ b/apps/bulldozer-js/src/databases/bulldozer/index.test.ts @@ -45,8 +45,8 @@ const initializedSnapshot = async (migrations: Parameters>, tableId: string, range: Record = {}, groupKey: PiledriverObject = null) => asRows(snapshot.listRowsInGroup({ tableId, groupKey, range })); -const set = (snapshot: Awaited>, tableId: string, rowIdentifier: string, newRowData: PiledriverObject | undefined) => - snapshot.setOrDeleteRow({ tableId, rowIdentifier, newRowData }); +const set = async (snapshot: Awaited>, tableId: string, rowIdentifier: string, newRowData: PiledriverObject | undefined) => + (await snapshot.setOrDeleteRow({ tableId, rowIdentifier, newRowData })).newSnapshot; describe("Bulldozer", () => { it("persists an empty snapshot for zero migrations", async () => { @@ -410,13 +410,13 @@ describe("Bulldozer", () => { ]); expect(reducerCalls).toEqual([{ rowIdentifier: "a", trigger: null, state: 0 }]); - snapshot = await snapshot.tick(new Date(firstTrigger)); + snapshot = (await snapshot.tick(new Date(firstTrigger))).newSnapshot; expect(await rows(snapshot, "time")).toEqual([ { groupKey: null, rowIdentifier: JSON.stringify(["a", 0]), rowSortKey: null, rowData: "A:initial" }, { groupKey: null, rowIdentifier: JSON.stringify(["a", 1]), rowSortKey: null, rowData: "A:2" }, ]); - snapshot = await snapshot.tick(new Date(secondTrigger)); + snapshot = (await snapshot.tick(new Date(secondTrigger))).newSnapshot; expect(await rows(snapshot, "time")).toEqual([ { groupKey: null, rowIdentifier: JSON.stringify(["a", 0]), rowSortKey: null, rowData: "A:initial" }, { groupKey: null, rowIdentifier: JSON.stringify(["a", 1]), rowSortKey: null, rowData: "A:2" }, @@ -460,7 +460,7 @@ describe("Bulldozer", () => { ]]); snapshot = await set(snapshot, "store", "a", "A"); - snapshot = await snapshot.tick(new Date(firstTrigger)); + snapshot = (await snapshot.tick(new Date(firstTrigger))).newSnapshot; expect(await rows(snapshot, "time")).toEqual([ { groupKey: null, rowIdentifier: JSON.stringify(["a", 0]), rowSortKey: null, rowData: "A:initial" }, { groupKey: null, rowIdentifier: JSON.stringify(["a", 1]), rowSortKey: null, rowData: "A:2" }, @@ -477,7 +477,7 @@ describe("Bulldozer", () => { // The hook's returned state and trigger drive subsequent timed steps: the next tick appends // (using the carried-over state) instead of replaying history. - snapshot = await snapshot.tick(new Date(secondTrigger)); + snapshot = (await snapshot.tick(new Date(secondTrigger))).newSnapshot; expect(await rows(snapshot, "time")).toEqual([ { groupKey: null, rowIdentifier: JSON.stringify(["a", 0]), rowSortKey: null, rowData: "A:initial" }, { groupKey: null, rowIdentifier: JSON.stringify(["a", 1]), rowSortKey: null, rowData: "A:2" }, diff --git a/apps/bulldozer-js/src/databases/bulldozer/index.ts b/apps/bulldozer-js/src/databases/bulldozer/index.ts index ec9044120..776caeca9 100644 --- a/apps/bulldozer-js/src/databases/bulldozer/index.ts +++ b/apps/bulldozer-js/src/databases/bulldozer/index.ts @@ -1,4 +1,5 @@ import { isShallowEqual } from "@hexclave/shared/dist/utils/arrays"; +import { inspect } from "node:util"; import { traceSpan } from "../../otel.js"; import { DatabaseSeq } from "../index.js"; import type { LowLevelDatabaseDebugSnapshot } from "../low-level/index.js"; @@ -22,12 +23,23 @@ async function fromAsync(iterable: AsyncIterable): Promise { * piledriverObjectEquals) is needed on top of a compareGroupKeys ordering: two group keys map * to the same string iff they are piledriverObjectEquals-equal. Object keys are sorted so that * key insertion order does not matter. + * + * Memoized by object identity: this function is called from B-tree comparators (twice per key + * comparison, O(log n) comparisons per tree operation), and CPU profiling showed it at ~5% of + * process CPU during backfills. Piledriver objects are immutable, so caching by identity is + * safe; the WeakMap lets group key objects be collected normally. */ +const canonicalGroupKeyStringCache = new WeakMap(); function canonicalGroupKeyString(groupKey: PiledriverObject): string { if (groupKey !== null && typeof groupKey === "object") { + const cached = canonicalGroupKeyStringCache.get(groupKey); + if (cached !== undefined) return cached; if (isPiledriverHeapObjectSymbol in groupKey) throw new Error("Group keys must not contain heap objects"); - if (Array.isArray(groupKey)) return "[" + groupKey.map(canonicalGroupKeyString).join(",") + "]"; - return "{" + Object.entries(groupKey).sort(([a], [b]) => compareStrings(a, b)).map(([k, v]) => JSON.stringify(k) + ":" + canonicalGroupKeyString(v)).join(",") + "}"; + const result = Array.isArray(groupKey) + ? "[" + groupKey.map(canonicalGroupKeyString).join(",") + "]" + : "{" + Object.entries(groupKey).sort(([a], [b]) => compareStrings(a, b)).map(([k, v]) => JSON.stringify(k) + ":" + canonicalGroupKeyString(v)).join(",") + "}"; + canonicalGroupKeyStringCache.set(groupKey, result); + return result; } return JSON.stringify(groupKey); } @@ -74,11 +86,157 @@ type TableChanges = { }[], }; type GroupChanges = Omit; +export type TableChangesDebugInfo = { + addedRows: number, + modifiedRows: number, + deletedRows: number, + addedGroups: number, + deletedGroups: number, + rowChanges: number, + groupChanges: number, +}; +export type BulldozerTableMutationDebugInfo = { + tableId: string, + phase: "source" | "downstream", + durationMs: number, + inputChangeCountsByInputTable: Record, + outputChangeCounts: TableChangesDebugInfo, +}; +export type BulldozerAffectedTableDebugInfo = { + tableId: string, + operationCount: number, + sourceOperationCount: number, + emitInputChangesOperationCount: number, + totalDurationMs: number, + sourceDurationMs: number, + emitInputChangesDurationMs: number, + inputChangeCountsByInputTable: Record, + totalInputChangeCounts: TableChangesDebugInfo, + outputChangeCounts: TableChangesDebugInfo, +}; +export type BulldozerSnapshotMutationDebugInfo = { + operation: "setOrDeleteRow" | "setOrDeleteRows" | "tick" | "applyTableMutation", + sourceTableId?: string, + rowsSetOrDeleted: number, + durationMs: number, + tableOperations: BulldozerTableMutationDebugInfo[], + affectedTableIds: string[], + affectedTables: Record, + totalOutputChangeCounts: TableChangesDebugInfo, +}; +export type BulldozerSnapshotMutationResult = { + newSnapshot: BulldozerDatabaseSnapshot, + debugInfo: BulldozerSnapshotMutationDebugInfo, +}; function appendAll(target: T[], values: Iterable) { for (const value of values) target.push(value); } +function tableChangesDebugInfo(changes: TableChanges): TableChangesDebugInfo { + return { + addedRows: changes.addedRows.length, + modifiedRows: changes.modifiedRows.length, + deletedRows: changes.deletedRows.length, + addedGroups: changes.addedGroups.length, + deletedGroups: changes.deletedGroups.length, + rowChanges: changes.addedRows.length + changes.modifiedRows.length + changes.deletedRows.length, + groupChanges: changes.addedGroups.length + changes.deletedGroups.length, + }; +} + +function emptyTableChangesDebugInfo(): TableChangesDebugInfo { + return { + addedRows: 0, + modifiedRows: 0, + deletedRows: 0, + addedGroups: 0, + deletedGroups: 0, + rowChanges: 0, + groupChanges: 0, + }; +} + +function mergeTableChangesDebugInfo(target: TableChangesDebugInfo, value: TableChangesDebugInfo) { + target.addedRows += value.addedRows; + target.modifiedRows += value.modifiedRows; + target.deletedRows += value.deletedRows; + target.addedGroups += value.addedGroups; + target.deletedGroups += value.deletedGroups; + target.rowChanges += value.rowChanges; + target.groupChanges += value.groupChanges; +} + +function inputChangeCountsByInputTable(changes: Record): Record { + return Object.fromEntries(Object.entries(changes).map(([inputTableKey, tableChanges]) => [inputTableKey, tableChangesDebugInfo(tableChanges)])); +} + +function emptyAffectedTableDebugInfo(tableId: string): BulldozerAffectedTableDebugInfo { + return { + tableId, + operationCount: 0, + sourceOperationCount: 0, + emitInputChangesOperationCount: 0, + totalDurationMs: 0, + sourceDurationMs: 0, + emitInputChangesDurationMs: 0, + inputChangeCountsByInputTable: {}, + totalInputChangeCounts: emptyTableChangesDebugInfo(), + outputChangeCounts: emptyTableChangesDebugInfo(), + }; +} + +function mergeInputChangeCounts( + target: Record, + totalTarget: TableChangesDebugInfo, + value: Record, +) { + for (const [inputTableKey, counts] of Object.entries(value)) { + target[inputTableKey] ??= emptyTableChangesDebugInfo(); + mergeTableChangesDebugInfo(target[inputTableKey], counts); + mergeTableChangesDebugInfo(totalTarget, counts); + } +} + +function affectedTablesDebugInfo(tableOperations: BulldozerTableMutationDebugInfo[]): Record { + const result = new Map(); + for (const operation of tableOperations) { + let table = result.get(operation.tableId); + if (table === undefined) { + table = emptyAffectedTableDebugInfo(operation.tableId); + result.set(operation.tableId, table); + } + + table.operationCount++; + table.totalDurationMs += operation.durationMs; + if (operation.phase === "source") { + table.sourceOperationCount++; + table.sourceDurationMs += operation.durationMs; + } else { + table.emitInputChangesOperationCount++; + table.emitInputChangesDurationMs += operation.durationMs; + } + mergeInputChangeCounts(table.inputChangeCountsByInputTable, table.totalInputChangeCounts, operation.inputChangeCountsByInputTable); + mergeTableChangesDebugInfo(table.outputChangeCounts, operation.outputChangeCounts); + } + return Object.fromEntries(result); +} + +function logSnapshotMutationDebugInfo(value: { + operation: BulldozerSnapshotMutationDebugInfo["operation"], + tableId: string | null, + rowsSetOrDeleted: number, + debugInfo: BulldozerSnapshotMutationDebugInfo, +}) { + if (value.rowsSetOrDeleted <= 0) return; + console.debug("bulldozer-js snapshot mutation", inspect(value, { + depth: null, + colors: false, + maxArrayLength: null, + breakLength: 160, + })); +} + function validateTableChanges(changes: TableChanges, context: string) { const deletedGroupKeys = new Set(changes.deletedGroups.map(group => canonicalGroupKeyString(group.groupKey))); const readdedGroup = changes.addedGroups.find(group => deletedGroupKeys.has(canonicalGroupKeyString(group.groupKey))); @@ -381,17 +539,28 @@ class BulldozerDatabaseSnapshot { tableId: string, rowIdentifier: string, newRowData: PiledriverObject | undefined, - }): Promise { + }): Promise { if (!(options.tableId in this.tablesState.tables)) throw new Error(`Table ${options.tableId} does not exist`); const setOrDeleteRow = this.tablesState.tables[options.tableId].table.setOrDeleteRow; if (!setOrDeleteRow) throw new Error("Table is not mutable"); - return await this._applyTableMutation(options.tableId, ({ serializedTable, inputTables }) => setOrDeleteRow({ - serializedTable, - inputTables, - rowIdentifier: options.rowIdentifier, - newRowData: options.newRowData, - })); + const result = await this._applyTableMutation({ + operation: "setOrDeleteRow", + tableId: options.tableId, + mutate: ({ serializedTable, inputTables }) => setOrDeleteRow({ + serializedTable, + inputTables, + rowIdentifier: options.rowIdentifier, + newRowData: options.newRowData, + }), + }); + logSnapshotMutationDebugInfo({ + operation: "setOrDeleteRow", + tableId: options.tableId, + rowsSetOrDeleted: result.debugInfo.rowsSetOrDeleted, + debugInfo: result.debugInfo, + }); + return result; } /** @@ -414,11 +583,30 @@ class BulldozerDatabaseSnapshot { async setOrDeleteRows(options: { tableId: string, rows: { rowIdentifier: string, newRowData: PiledriverObject | undefined }[], - }): Promise { + }): Promise { if (!(options.tableId in this.tablesState.tables)) throw new Error(`Table ${options.tableId} does not exist`); const setOrDeleteRow = this.tablesState.tables[options.tableId].table.setOrDeleteRow; if (!setOrDeleteRow) throw new Error("Table is not mutable"); - if (options.rows.length === 0) return this; + if (options.rows.length === 0) { + const debugInfo: BulldozerSnapshotMutationDebugInfo = { + operation: "setOrDeleteRows", + sourceTableId: options.tableId, + rowsSetOrDeleted: 0, + durationMs: 0, + tableOperations: [], + affectedTableIds: [], + affectedTables: {}, + totalOutputChangeCounts: emptyTableChangesDebugInfo(), + }; + const result = { newSnapshot: this, debugInfo }; + logSnapshotMutationDebugInfo({ + operation: "setOrDeleteRows", + tableId: options.tableId, + rowsSetOrDeleted: 0, + debugInfo, + }); + return result; + } const seenIdentifiers = new Set(); for (const row of options.rows) { @@ -426,93 +614,174 @@ class BulldozerDatabaseSnapshot { seenIdentifiers.add(row.rowIdentifier); } - return await this._applyTableMutation(options.tableId, async ({ serializedTable, inputTables }) => { - let currentSerializedTable = serializedTable; - const combined: TableChanges = { addedRows: [], modifiedRows: [], deletedRows: [], addedGroups: [], deletedGroups: [] }; - for (const row of options.rows) { - const result = await setOrDeleteRow({ - serializedTable: currentSerializedTable, - inputTables, - rowIdentifier: row.rowIdentifier, - newRowData: row.newRowData, - }); - currentSerializedTable = result.newSerializedTable; - mergeTableChanges(combined, result.outputChanges); - } - normalizeGroupLifecycle(combined); - return { newSerializedTable: currentSerializedTable, outputChanges: combined }; + const result = await this._applyTableMutation({ + operation: "setOrDeleteRows", + tableId: options.tableId, + mutate: async ({ serializedTable, inputTables }) => { + let currentSerializedTable = serializedTable; + const combined: TableChanges = { addedRows: [], modifiedRows: [], deletedRows: [], addedGroups: [], deletedGroups: [] }; + for (const row of options.rows) { + const result = await setOrDeleteRow({ + serializedTable: currentSerializedTable, + inputTables, + rowIdentifier: row.rowIdentifier, + newRowData: row.newRowData, + }); + currentSerializedTable = result.newSerializedTable; + mergeTableChanges(combined, result.outputChanges); + } + normalizeGroupLifecycle(combined); + return { newSerializedTable: currentSerializedTable, outputChanges: combined }; + }, }); + logSnapshotMutationDebugInfo({ + operation: "setOrDeleteRows", + tableId: options.tableId, + rowsSetOrDeleted: result.debugInfo.rowsSetOrDeleted, + debugInfo: result.debugInfo, + }); + return result; } - async tick(now: Date): Promise { + async tick(now: Date): Promise { + const startedAt = performance.now(); let snapshot: BulldozerDatabaseSnapshot = this; + const tableOperations: BulldozerTableMutationDebugInfo[] = []; + const affectedTableIds = new Set(); + const totalOutputChangeCounts = emptyTableChangesDebugInfo(); + let rowsSetOrDeleted = 0; for (const [tableId, tableState] of Object.entries(this.tablesState.tables)) { const tick = tableState.table.tick; if (!tick) continue; - snapshot = await snapshot._applyTableMutation(tableId, ({ serializedTable, inputTables }) => tick({ serializedTable, inputTables, now })); + const result = await snapshot._applyTableMutation({ + operation: "tick", + tableId, + mutate: ({ serializedTable, inputTables }) => tick({ serializedTable, inputTables, now }), + }); + snapshot = result.newSnapshot; + tableOperations.push(...result.debugInfo.tableOperations); + for (const affectedTableId of result.debugInfo.affectedTableIds) affectedTableIds.add(affectedTableId); + mergeTableChangesDebugInfo(totalOutputChangeCounts, result.debugInfo.totalOutputChangeCounts); + rowsSetOrDeleted += result.debugInfo.rowsSetOrDeleted; } - return snapshot; + const debugInfo: BulldozerSnapshotMutationDebugInfo = { + operation: "tick", + rowsSetOrDeleted, + durationMs: performance.now() - startedAt, + tableOperations, + affectedTableIds: [...affectedTableIds], + affectedTables: affectedTablesDebugInfo(tableOperations), + totalOutputChangeCounts, + }; + logSnapshotMutationDebugInfo({ + operation: "tick", + tableId: null, + rowsSetOrDeleted, + debugInfo, + }); + return { newSnapshot: snapshot, debugInfo }; } - private async _applyTableMutation( + private async _applyTableMutation(options: { + operation: BulldozerSnapshotMutationDebugInfo["operation"], tableId: string, mutate: (options: { serializedTable: PiledriverObject, inputTables: Record, }) => Promise<{ newSerializedTable: PiledriverObject, outputChanges: TableChanges }>, - ): Promise { - return await traceSpan({ description: "bulldozer-js.bulldozer.applyTableMutation", attributes: { "bulldozer.table_id": tableId } }, async () => { + }): Promise { + const startedAt = performance.now(); + return await traceSpan({ description: "bulldozer-js.bulldozer.applyTableMutation", attributes: { "bulldozer.table_id": options.tableId } }, async () => { const tablesState = this.tablesState; const serializedTables = { ...this.serialized.serializedTables }; const pending = new Map>(); const remainingInputs = new Map(); + const tableOperations: BulldozerTableMutationDebugInfo[] = []; + const affectedTableIds = new Set(); + const totalOutputChangeCounts = emptyTableChangesDebugInfo(); const inputTables = (id: string) => createInputTables(tablesState.tables, inputId => serializedTables[inputId], id); const emptyChanges = (): TableChanges => ({ addedRows: [], modifiedRows: [], deletedRows: [], addedGroups: [], deletedGroups: [] }); const hasChanges = (changes: TableChanges) => changes.addedRows.length || changes.modifiedRows.length || changes.deletedRows.length || changes.addedGroups.length || changes.deletedGroups.length; const addPending = (tableId: string, inputTableKey: string, changes: TableChanges) => { if (!hasChanges(changes)) return; - pending.set(tableId, { ...pending.get(tableId), [inputTableKey]: changes }); + pending.set(tableId, { ...pending.get(tableId), [inputTableKey]: changes }); }; - for (const queue = [tableId], seen = new Set([tableId]); queue.length;) { + for (const queue = [options.tableId], seen = new Set([options.tableId]); queue.length;) { for (const outputTable of tablesState.tables[queue.shift()!].outputTables) { - remainingInputs.set(outputTable.tableId, (remainingInputs.get(outputTable.tableId) ?? 0) + 1); - if (!seen.has(outputTable.tableId)) { - seen.add(outputTable.tableId); + remainingInputs.set(outputTable.tableId, (remainingInputs.get(outputTable.tableId) ?? 0) + 1); + if (!seen.has(outputTable.tableId)) { + seen.add(outputTable.tableId); + queue.push(outputTable.tableId); + } + } + } + + const sourceStartedAt = performance.now(); + const first = await traceSpan({ description: "bulldozer-js.bulldozer.mutateSourceTable", attributes: { "bulldozer.table_id": options.tableId } }, async () => await options.mutate({ serializedTable: serializedTables[options.tableId], inputTables: inputTables(options.tableId) })); + validateTableChanges(first.outputChanges, `Table ${options.tableId} output`); + const sourceOutputChangeCounts = tableChangesDebugInfo(first.outputChanges); + tableOperations.push({ + tableId: options.tableId, + phase: "source", + durationMs: performance.now() - sourceStartedAt, + inputChangeCountsByInputTable: {}, + outputChangeCounts: sourceOutputChangeCounts, + }); + affectedTableIds.add(options.tableId); + mergeTableChangesDebugInfo(totalOutputChangeCounts, sourceOutputChangeCounts); + serializedTables[options.tableId] = first.newSerializedTable; + for (const outputTable of tablesState.tables[options.tableId].outputTables) addPending(outputTable.tableId, outputTable.inputTableKey, first.outputChanges); + + for (const queue = tablesState.tables[options.tableId].outputTables.map(outputTable => outputTable.tableId); queue.length;) { + const downstreamTableId = queue.shift()!; + const left = (remainingInputs.get(downstreamTableId) ?? 1) - 1; + remainingInputs.set(downstreamTableId, left); + if (left > 0) continue; + const table = tablesState.tables[downstreamTableId]; + const changes = pending.get(downstreamTableId); + if (changes) { + const normalizedChanges = Object.fromEntries(Object.keys(table.inputTableIds).map(inputTableKey => [inputTableKey, changes[inputTableKey] ?? emptyChanges()])); + const downstreamStartedAt = performance.now(); + const result = await traceSpan({ description: "bulldozer-js.bulldozer.emitInputChanges", attributes: { "bulldozer.table_id": downstreamTableId } }, async () => await table.table.emitInputChanges({ + serializedTable: serializedTables[downstreamTableId], + inputTables: inputTables(downstreamTableId), + changes: normalizedChanges, + })); + validateTableChanges(result.outputChanges, `Table ${downstreamTableId} output`); + const outputChangeCounts = tableChangesDebugInfo(result.outputChanges); + tableOperations.push({ + tableId: downstreamTableId, + phase: "downstream", + durationMs: performance.now() - downstreamStartedAt, + inputChangeCountsByInputTable: inputChangeCountsByInputTable(normalizedChanges), + outputChangeCounts, + }); + affectedTableIds.add(downstreamTableId); + mergeTableChangesDebugInfo(totalOutputChangeCounts, outputChangeCounts); + serializedTables[downstreamTableId] = result.newSerializedTable; + for (const outputTable of table.outputTables) addPending(outputTable.tableId, outputTable.inputTableKey, result.outputChanges); + } + for (const outputTable of table.outputTables) { queue.push(outputTable.tableId); } - } } - const first = await traceSpan({ description: "bulldozer-js.bulldozer.mutateSourceTable", attributes: { "bulldozer.table_id": tableId } }, async () => await mutate({ serializedTable: serializedTables[tableId], inputTables: inputTables(tableId) })); - validateTableChanges(first.outputChanges, `Table ${tableId} output`); - serializedTables[tableId] = first.newSerializedTable; - for (const outputTable of tablesState.tables[tableId].outputTables) addPending(outputTable.tableId, outputTable.inputTableKey, first.outputChanges); - - for (const queue = tablesState.tables[tableId].outputTables.map(outputTable => outputTable.tableId); queue.length;) { - const downstreamTableId = queue.shift()!; - const left = (remainingInputs.get(downstreamTableId) ?? 1) - 1; - remainingInputs.set(downstreamTableId, left); - if (left > 0) continue; - const table = tablesState.tables[downstreamTableId]; - const changes = pending.get(downstreamTableId); - if (changes) { - const result = await traceSpan({ description: "bulldozer-js.bulldozer.emitInputChanges", attributes: { "bulldozer.table_id": downstreamTableId } }, async () => await table.table.emitInputChanges({ - serializedTable: serializedTables[downstreamTableId], - inputTables: inputTables(downstreamTableId), - changes: Object.fromEntries(Object.keys(table.inputTableIds).map(inputTableKey => [inputTableKey, changes[inputTableKey] ?? emptyChanges()])), - })); - validateTableChanges(result.outputChanges, `Table ${downstreamTableId} output`); - serializedTables[downstreamTableId] = result.newSerializedTable; - for (const outputTable of table.outputTables) addPending(outputTable.tableId, outputTable.inputTableKey, result.outputChanges); - } - for (const outputTable of table.outputTables) { - queue.push(outputTable.tableId); - } - } - - return new BulldozerDatabaseSnapshot({ ...this.serialized, serializedTables, uniqueSnapshotIdentifier: crypto.randomUUID() }, this.tablesState); + const debugInfo: BulldozerSnapshotMutationDebugInfo = { + operation: options.operation, + sourceTableId: options.tableId, + rowsSetOrDeleted: totalOutputChangeCounts.rowChanges, + durationMs: performance.now() - startedAt, + tableOperations, + affectedTableIds: [...affectedTableIds], + affectedTables: affectedTablesDebugInfo(tableOperations), + totalOutputChangeCounts, + }; + return { + newSnapshot: new BulldozerDatabaseSnapshot({ ...this.serialized, serializedTables, uniqueSnapshotIdentifier: crypto.randomUUID() }, this.tablesState), + debugInfo, + }; }); } } @@ -579,12 +848,13 @@ function createTablesStateFromMigrations(migrations: readonly BulldozerDatabaseM } export type BulldozerDatabase = { + getDebugInfo(): any, listTables(): BulldozerDatabaseTableDescriptor[], debugPiledriverSnapshot?(): Promise, debugLowLevelSnapshot?(): Promise, getSnapshot(): Promise<{ snapshot: BulldozerDatabaseSnapshot, seq: DatabaseSeq }>, - withSnapshot(updateSnapshot: (snapshot: BulldozerDatabaseSnapshot) => Promise): Promise<{ snapshot: BulldozerDatabaseSnapshot, seq: DatabaseSeq }>, - withSnapshotReplicated(updateSnapshot: (snapshot: BulldozerDatabaseSnapshot) => Promise): Promise<{ snapshot: BulldozerDatabaseSnapshot, seq: DatabaseSeq }>, + withSnapshot(updateSnapshot: (snapshot: BulldozerDatabaseSnapshot) => Promise): Promise<{ snapshot: BulldozerDatabaseSnapshot, seq: DatabaseSeq }>, + withSnapshotReplicated(updateSnapshot: (snapshot: BulldozerDatabaseSnapshot) => Promise): Promise<{ snapshot: BulldozerDatabaseSnapshot, seq: DatabaseSeq }>, applyRemainingMigrations(): Promise<{ seq: DatabaseSeq }>, }; @@ -624,23 +894,80 @@ export function declareBulldozerDatabase(piledriverDatabase: PiledriverDatabase, }; }); const withSnapshot = async ( - updateSnapshot: (snapshot: BulldozerDatabaseSnapshot) => Promise, + updateSnapshot: (snapshot: BulldozerDatabaseSnapshot) => Promise, options: { replicated: boolean }, ) => { return await traceSpan({ description: "bulldozer-js.bulldozer.withSnapshot", attributes: { "bulldozer.replicated": options.replicated } }, async () => { + const startedAt = performance.now(); + let writeLockWaitMs = 0; + let getSnapshotMs = 0; + let updateSnapshotMs = 0; + let toPiledriverObjectMs = 0; + let setRootMs = 0; + let waitUntilAvailableMs = 0; + let waitUntilReplicatedMs = 0; + let mutationDebugInfo: BulldozerSnapshotMutationDebugInfo | undefined; + const writeLockWaitStartedAt = performance.now(); const result = await withWriteLock(async () => { + writeLockWaitMs = performance.now() - writeLockWaitStartedAt; + const getSnapshotStartedAt = performance.now(); const { snapshot } = await getSnapshot(); - const newSnapshot = await updateSnapshot(snapshot); - const { seq } = await setRoot({ snapshot: newSnapshot.toPiledriverObject() }); + getSnapshotMs = performance.now() - getSnapshotStartedAt; + const updateSnapshotStartedAt = performance.now(); + const updateResult = await updateSnapshot(snapshot); + updateSnapshotMs = performance.now() - updateSnapshotStartedAt; + mutationDebugInfo = updateResult instanceof BulldozerDatabaseSnapshot ? undefined : updateResult.debugInfo; + const newSnapshot = updateResult instanceof BulldozerDatabaseSnapshot ? updateResult : updateResult.newSnapshot; + const toPiledriverObjectStartedAt = performance.now(); + const newSnapshotPiledriverObject = newSnapshot.toPiledriverObject(); + toPiledriverObjectMs = performance.now() - toPiledriverObjectStartedAt; + const setRootStartedAt = performance.now(); + const { seq } = await setRoot({ snapshot: newSnapshotPiledriverObject }); + setRootMs = performance.now() - setRootStartedAt; + const waitUntilAvailableStartedAt = performance.now(); await piledriverDatabase.waitUntilAvailable(seq); + waitUntilAvailableMs = performance.now() - waitUntilAvailableStartedAt; return { snapshot: newSnapshot, seq }; }); - if (options.replicated) await piledriverDatabase.waitUntilReplicated(result.seq); + if (options.replicated) { + const waitUntilReplicatedStartedAt = performance.now(); + await piledriverDatabase.waitUntilReplicated(result.seq); + waitUntilReplicatedMs = performance.now() - waitUntilReplicatedStartedAt; + } + console.debug("bulldozer-js withSnapshot timing", inspect({ + replicated: options.replicated, + elapsedMs: performance.now() - startedAt, + writeLockWaitMs, + getSnapshotMs, + updateSnapshotMs, + toPiledriverObjectMs, + setRootMs, + waitUntilAvailableMs, + waitUntilReplicatedMs, + mutation: mutationDebugInfo === undefined ? undefined : { + operation: mutationDebugInfo.operation, + sourceTableId: mutationDebugInfo.sourceTableId, + rowsSetOrDeleted: mutationDebugInfo.rowsSetOrDeleted, + durationMs: mutationDebugInfo.durationMs, + }, + }, { depth: null, maxArrayLength: null })); return result; }); }; return { + getDebugInfo() { + return { + backend: "bulldozer", + constructorArguments: { piledriverDatabase, options }, + piledriverDatabase, + rootKey, + getRoot, + setRoot, + tablesState, + currentOperation, + }; + }, listTables: () => Object.entries(tablesState.tables).map(([tableId, tableState]) => ({ tableId, inputTableIds: { ...tableState.inputTableIds }, @@ -2041,7 +2368,11 @@ export function declareLeftJoinTable(options: { const addRight = async (row: InputRow) => { const right: StoredRow = { ...row, joinKey: await options.rightJoinKeyExtractor(row) }; const lefts = await leftMatches(right.joinKey); - if (!(await state.rightByJoinKey.getAll(right.joinKey)).length) for (const left of lefts) await deleteOutput(left, null); + // hasAny (O(depth)) instead of getAll().length: many rows can share one join key (e.g. + // a null-ish key on most rows), and materializing all of them per inserted row makes + // bulk ingestion O(n^2). The check is only needed when there are matching lefts whose + // left-with-null output row must be retracted. + if (lefts.length > 0 && !(await state.rightByJoinKey.hasAny(right.joinKey))) for (const left of lefts) await deleteOutput(left, null); state = { ...state, rightRows: await state.rightRows.set(right.rowIdentifier, right), rightByJoinKey: await state.rightByJoinKey.add(right.joinKey, right.rowIdentifier, right.rowIdentifier) }; for (const left of lefts) await addOutput(left, right); }; @@ -2051,7 +2382,7 @@ export function declareLeftJoinTable(options: { const lefts = await leftMatches(right.joinKey); for (const left of lefts) await deleteOutput(left, right); state = { ...state, rightRows: await state.rightRows.delete(right.rowIdentifier), rightByJoinKey: await state.rightByJoinKey.delete(right.joinKey, right.rowIdentifier) }; - if (!(await state.rightByJoinKey.getAll(right.joinKey)).length) for (const left of lefts) await addOutput(left, null); + if (lefts.length > 0 && !(await state.rightByJoinKey.hasAny(right.joinKey))) for (const left of lefts) await addOutput(left, null); }; for (const row of changedRowsFromTableChanges(changes.left)) { diff --git a/apps/bulldozer-js/src/databases/bulldozer/performance.test.ts b/apps/bulldozer-js/src/databases/bulldozer/performance.test.ts index db12f5ecc..03373df8a 100644 --- a/apps/bulldozer-js/src/databases/bulldozer/performance.test.ts +++ b/apps/bulldozer-js/src/databases/bulldozer/performance.test.ts @@ -94,8 +94,8 @@ async function initializedSnapshot(migrations: Migration) { await db.applyRemainingMigrations(); return (await db.getSnapshot()).snapshot; } -const set = (snapshot: Snapshot, tableId: string, rowIdentifier: string, newRowData: PiledriverObject | undefined) => - snapshot.setOrDeleteRow({ tableId, rowIdentifier, newRowData }); +const set = async (snapshot: Snapshot, tableId: string, rowIdentifier: string, newRowData: PiledriverObject | undefined) => + (await snapshot.setOrDeleteRow({ tableId, rowIdentifier, newRowData })).newSnapshot; const seedRows = async ( snapshot: Snapshot, tableId: string, diff --git a/apps/bulldozer-js/src/databases/index.ts b/apps/bulldozer-js/src/databases/index.ts index a8fdbc5be..68a48c417 100644 --- a/apps/bulldozer-js/src/databases/index.ts +++ b/apps/bulldozer-js/src/databases/index.ts @@ -1,6 +1,7 @@ export type DatabaseSeq = (readonly (string | number)[] & { __brand: "hexclave-low-level-kv-store-seq" }); export type Database = { + getDebugInfo(): any, /** * Returns a promise that resolves once it is guaranteed that queries made from this database client will see the * given seq. diff --git a/apps/bulldozer-js/src/databases/low-level/implementations/in-memory.ts b/apps/bulldozer-js/src/databases/low-level/implementations/in-memory.ts index ecb5e3ef7..6ff04ae12 100644 --- a/apps/bulldozer-js/src/databases/low-level/implementations/in-memory.ts +++ b/apps/bulldozer-js/src/databases/low-level/implementations/in-memory.ts @@ -1,6 +1,6 @@ import { encodeBase64 } from "@hexclave/shared/dist/utils/bytes"; import { stringCompare } from "@hexclave/shared/dist/utils/strings"; -import { traceSpan } from "../../../otel.js"; +import { traceSpanHot } from "../../../otel.js"; import { Database, DatabaseSeq } from "../../index.js"; import { LowLevelDatabase, LowLevelDatabaseDebugEntry, LowLevelKvDump, LowLevelKvStore } from "../index.js"; @@ -47,7 +47,7 @@ export function declareInMemoryLowLevelDatabase(dbId: string): LowLevelDatabase const seqSentinel: DatabaseSeq = [] as unknown as DatabaseSeq; const result: LowLevelKvStore & LowLevelKvDump = { async get(key: ArrayBuffer) { - return await traceSpan({ description: "bulldozer-js.low-level.in-memory.get", attributes }, async () => { + return await traceSpanHot({ description: "bulldozer-js.low-level.in-memory.get", attributes }, async () => { if (key.byteLength > 64) throw new Error("KV store key must be <= 64 bytes"); return { buffer: base64KeyToValue.get(encodeBase64(new Uint8Array(key)))?.slice(0) ?? null, @@ -56,7 +56,7 @@ export function declareInMemoryLowLevelDatabase(dbId: string): LowLevelDatabase }); }, async setAll(entries: Array<{ key: ArrayBuffer, value: ArrayBuffer }>) { - return await traceSpan({ description: "bulldozer-js.low-level.in-memory.setAll", attributes: { ...attributes, "bulldozer.low_level.entry_count": entries.length } }, async () => { + return await traceSpanHot({ description: "bulldozer-js.low-level.in-memory.setAll", attributes: { ...attributes, "bulldozer.low_level.entry_count": entries.length } }, async () => { for (const { key, value } of entries) { if (key.byteLength > 64) throw new Error("KV store key must be <= 64 bytes"); if (value.byteLength > 2_000_000_000) throw new Error("KV store value must be <= 2GB"); @@ -68,7 +68,7 @@ export function declareInMemoryLowLevelDatabase(dbId: string): LowLevelDatabase }); }, async deleteAll(keys: ArrayBuffer[]) { - return await traceSpan({ description: "bulldozer-js.low-level.in-memory.deleteAll", attributes: { ...attributes, "bulldozer.low_level.key_count": keys.length } }, async () => { + return await traceSpanHot({ description: "bulldozer-js.low-level.in-memory.deleteAll", attributes: { ...attributes, "bulldozer.low_level.key_count": keys.length } }, async () => { for (const key of keys) { if (key.byteLength > 64) throw new Error("KV store key must be <= 64 bytes"); base64KeyToValue.delete(encodeBase64(new Uint8Array(key))); @@ -79,7 +79,7 @@ export function declareInMemoryLowLevelDatabase(dbId: string): LowLevelDatabase }); }, async insertAll(values: ArrayBuffer[], options: { requiresSeq: DatabaseSeq }) { - return await traceSpan({ description: "bulldozer-js.low-level.in-memory.insertAll", attributes: { ...attributes, "bulldozer.low_level.value_count": values.length } }, async () => { + return await traceSpanHot({ description: "bulldozer-js.low-level.in-memory.insertAll", attributes: { ...attributes, "bulldozer.low_level.value_count": values.length } }, async () => { for (const value of values) { if (value.byteLength > 2_000_000_000) throw new Error("KV store value must be <= 2GB"); } @@ -91,7 +91,7 @@ export function declareInMemoryLowLevelDatabase(dbId: string): LowLevelDatabase }); }, async compareAndSet(key: ArrayBuffer, compare: ArrayBuffer, value: ArrayBuffer, options: { requiresSeq: DatabaseSeq }) { - return await traceSpan({ description: "bulldozer-js.low-level.in-memory.compareAndSet", attributes }, async () => { + return await traceSpanHot({ description: "bulldozer-js.low-level.in-memory.compareAndSet", attributes }, async () => { if (key.byteLength > 64) throw new Error("KV store key must be <= 64 bytes"); if (compare.byteLength > 2_000_000_000) throw new Error("KV store compare must be <= 2GB"); if (value.byteLength > 2_000_000_000) throw new Error("KV store value must be <= 2GB"); @@ -107,7 +107,7 @@ export function declareInMemoryLowLevelDatabase(dbId: string): LowLevelDatabase }); }, async debugEntries() { - return await traceSpan({ description: "bulldozer-js.low-level.in-memory.debugEntries", attributes }, async () => [...base64KeyToValue.entries()] + return await traceSpanHot({ description: "bulldozer-js.low-level.in-memory.debugEntries", attributes }, async () => [...base64KeyToValue.entries()] .sort(([a], [b]) => stringCompare(a, b)) .map(([keyBase64, value]) => { const keyBytes = Buffer.from(keyBase64, "base64"); @@ -127,8 +127,15 @@ export function declareInMemoryLowLevelDatabase(dbId: string): LowLevelDatabase return result; }; - return { + getDebugInfo() { + return { + backend: "in-memory", + constructorArguments: { dbId }, + inMemoryLowLevelKvStores, + debugEntriesByStoreId, + }; + }, declareKvDump(dumpId) { return declareInMemoryLowLevelKvStoreOrDump("dump", JSON.stringify([dbId, dumpId])); }, @@ -136,19 +143,19 @@ export function declareInMemoryLowLevelDatabase(dbId: string): LowLevelDatabase return declareInMemoryLowLevelKvStoreOrDump("store", JSON.stringify([dbId, storeId])); }, async waitUntilAvailable() { - return await traceSpan({ description: "bulldozer-js.low-level.in-memory.waitUntilAvailable", attributes: { "bulldozer.low_level.backend": "in-memory" } }, async () => {}); + return await traceSpanHot({ description: "bulldozer-js.low-level.in-memory.waitUntilAvailable", attributes: { "bulldozer.low_level.backend": "in-memory" } }, async () => {}); }, async waitUntilDurable() { - return await traceSpan({ description: "bulldozer-js.low-level.in-memory.waitUntilDurable", attributes: { "bulldozer.low_level.backend": "in-memory" } }, async () => {}); + return await traceSpanHot({ description: "bulldozer-js.low-level.in-memory.waitUntilDurable", attributes: { "bulldozer.low_level.backend": "in-memory" } }, async () => {}); }, async waitUntilReplicated() { - return await traceSpan({ description: "bulldozer-js.low-level.in-memory.waitUntilReplicated", attributes: { "bulldozer.low_level.backend": "in-memory" } }, async () => {}); + return await traceSpanHot({ description: "bulldozer-js.low-level.in-memory.waitUntilReplicated", attributes: { "bulldozer.low_level.backend": "in-memory" } }, async () => {}); }, combineSeqs(...seqs) { return this.initialSeq; }, async debugSnapshot() { - return await traceSpan({ description: "bulldozer-js.low-level.in-memory.debugSnapshot", attributes: { "bulldozer.low_level.backend": "in-memory" } }, async () => { + return await traceSpanHot({ description: "bulldozer-js.low-level.in-memory.debugSnapshot", attributes: { "bulldozer.low_level.backend": "in-memory" } }, async () => { const stores: Record = {}; const dumps: Record = {}; for (const [storeId, entries] of debugEntriesByStoreId.entries()) { diff --git a/apps/bulldozer-js/src/databases/low-level/implementations/instant-availability.test.ts b/apps/bulldozer-js/src/databases/low-level/implementations/instant-availability.test.ts index d8a013c2b..030d0c993 100644 --- a/apps/bulldozer-js/src/databases/low-level/implementations/instant-availability.test.ts +++ b/apps/bulldozer-js/src/databases/low-level/implementations/instant-availability.test.ts @@ -38,6 +38,16 @@ function createSlowSetDatabase() { }, }; const db: LowLevelDatabase = { + getDebugInfo() { + return { + backend: "slow-set-test", + releaseSets, + setCallCount, + committed, + seqToPromise, + initialSeq, + }; + }, declareKvStore: () => store, declareKvDump: () => { throw new Error("not implemented"); diff --git a/apps/bulldozer-js/src/databases/low-level/implementations/instant-availability.ts b/apps/bulldozer-js/src/databases/low-level/implementations/instant-availability.ts index 329a722c2..937fcce8a 100644 --- a/apps/bulldozer-js/src/databases/low-level/implementations/instant-availability.ts +++ b/apps/bulldozer-js/src/databases/low-level/implementations/instant-availability.ts @@ -1,6 +1,6 @@ import { encodeBase64 } from "@hexclave/shared/dist/utils/bytes"; import { captureError } from "@hexclave/shared/dist/utils/errors"; -import { traceSpan } from "../../../otel.js"; +import { traceSpanHot } from "../../../otel.js"; import { DatabaseSeq } from "../../index.js"; import { LowLevelDatabase, LowLevelKvDump, LowLevelKvStore } from "../index.js"; @@ -84,14 +84,14 @@ export function declareInstantAvailabilityLowLevelDatabase(wrapped: LowLevelData }); }; const waitForPendingSeqRecordBudget = async () => { - await traceSpan({ description: "bulldozer-js.low-level.instant.waitForPendingSeqRecordBudget", attributes: { "bulldozer.low_level.backend": "instant-availability" } }, async () => { + await traceSpanHot({ description: "bulldozer-js.low-level.instant.waitForPendingSeqRecordBudget", attributes: { "bulldozer.low_level.backend": "instant-availability" } }, async () => { while (pendingSeqRecords.size >= maxPendingSeqRecords) { await pendingSeqRecordsChanged; } }); }; const withWriteGate = async (operation: () => Promise): Promise => { - return await traceSpan({ description: "bulldozer-js.low-level.instant.withWriteGate", attributes: { "bulldozer.low_level.backend": "instant-availability" } }, async () => { + return await traceSpanHot({ description: "bulldozer-js.low-level.instant.withWriteGate", attributes: { "bulldozer.low_level.backend": "instant-availability" } }, async () => { const previousOperation = currentWriteGateOperation; let releaseCurrentOperation: () => void; currentWriteGateOperation = new Promise(resolve => { @@ -109,7 +109,7 @@ export function declareInstantAvailabilityLowLevelDatabase(wrapped: LowLevelData const createSeq = (underlyingSeq: Promise) => { const seq = toSeq(crypto.randomUUID()); underlyingSeq.catch(() => {}); - const underlyingAvailable = traceSpan({ description: "bulldozer-js.low-level.instant.underlyingAvailable", attributes: { "bulldozer.low_level.backend": "instant-availability" } }, async () => { + const underlyingAvailable = traceSpanHot({ description: "bulldozer-js.low-level.instant.underlyingAvailable", attributes: { "bulldozer.low_level.backend": "instant-availability" } }, async () => { const resolvedUnderlyingSeq = await underlyingSeq; await wrapped.waitUntilAvailable(resolvedUnderlyingSeq); }); @@ -169,7 +169,7 @@ export function declareInstantAvailabilityLowLevelDatabase(wrapped: LowLevelData const result: LowLevelKvStore & LowLevelKvDump = { async get(key) { - return await traceSpan({ description: "bulldozer-js.low-level.instant.get", attributes }, async (span) => { + return await traceSpanHot({ description: "bulldozer-js.low-level.instant.get", attributes }, async (span) => { const cached = cachedValues.get(cacheKey(key)); span.setAttribute("bulldozer.low_level.instant.cache_hit", cached !== undefined); if (cached !== undefined) { @@ -185,13 +185,13 @@ export function declareInstantAvailabilityLowLevelDatabase(wrapped: LowLevelData }); }, async setAll(entries, setOptions) { - return await traceSpan({ description: "bulldozer-js.low-level.instant.setAll", attributes: { ...attributes, "bulldozer.low_level.entry_count": entries.length } }, async () => { + return await traceSpanHot({ description: "bulldozer-js.low-level.instant.setAll", attributes: { ...attributes, "bulldozer.low_level.entry_count": entries.length } }, async () => { if (entries.length === 0) return { seq: setOptions?.requiresSeq ?? initialSeq }; return await withWriteGate(async () => setAllLocked(entries, setOptions)); }); }, async deleteAll(keys) { - return await traceSpan({ description: "bulldozer-js.low-level.instant.deleteAll", attributes: { ...attributes, "bulldozer.low_level.key_count": keys.length } }, async () => { + return await traceSpanHot({ description: "bulldozer-js.low-level.instant.deleteAll", attributes: { ...attributes, "bulldozer.low_level.key_count": keys.length } }, async () => { if (keys.length === 0) return { seq: initialSeq }; return await withWriteGate(async () => { const keysForWrapped = keys.map(cloneArrayBuffer); @@ -207,7 +207,7 @@ export function declareInstantAvailabilityLowLevelDatabase(wrapped: LowLevelData }); }, async insertAll(values, insertOptions) { - return await traceSpan({ description: "bulldozer-js.low-level.instant.insertAll", attributes: { ...attributes, "bulldozer.low_level.value_count": values.length } }, async () => { + return await traceSpanHot({ description: "bulldozer-js.low-level.instant.insertAll", attributes: { ...attributes, "bulldozer.low_level.value_count": values.length } }, async () => { if (values.length === 0) return { keys: [], seq: insertOptions?.requiresSeq ?? initialSeq }; return await withWriteGate(async () => { const valuesForWrapped = values.map(cloneArrayBuffer); @@ -221,7 +221,7 @@ export function declareInstantAvailabilityLowLevelDatabase(wrapped: LowLevelData }); }, async compareAndSet(key, compare, value, compareAndSetOptions) { - return await traceSpan({ description: "bulldozer-js.low-level.instant.compareAndSet", attributes }, async () => { + return await traceSpanHot({ description: "bulldozer-js.low-level.instant.compareAndSet", attributes }, async () => { // The read+compare must happen inside the SAME write-gate critical section as the // subsequent write; otherwise two concurrent calls could both read the same value, // both pass the comparison, and both write — each returning wasSet: true, defeating @@ -235,7 +235,7 @@ export function declareInstantAvailabilityLowLevelDatabase(wrapped: LowLevelData }); }, async debugEntries() { - return await traceSpan({ description: "bulldozer-js.low-level.instant.debugEntries", attributes }, async () => await wrappedStore.debugEntries?.() ?? []); + return await traceSpanHot({ description: "bulldozer-js.low-level.instant.debugEntries", attributes }, async () => await wrappedStore.debugEntries?.() ?? []); }, }; @@ -243,6 +243,23 @@ export function declareInstantAvailabilityLowLevelDatabase(wrapped: LowLevelData }; return { + getDebugInfo() { + return { + backend: "instant-availability", + constructorArguments: { wrapped, options }, + wrapped, + dbId, + maxPendingSeqRecords, + initialSeq, + seqRecords, + createdSeqRecords, + underlyingAvailableSeqRecords, + pendingSeqRecords, + currentWriteGateOperation, + pendingSeqRecordsChanged, + cacheMaps, + }; + }, declareKvStore(id) { return declareStoreOrDump(wrapped.declareKvStore(id) as LowLevelKvStore & LowLevelKvDump); }, @@ -250,13 +267,13 @@ export function declareInstantAvailabilityLowLevelDatabase(wrapped: LowLevelData return declareStoreOrDump(wrapped.declareKvDump(id) as LowLevelKvStore & LowLevelKvDump); }, async waitUntilAvailable() { - return await traceSpan({ description: "bulldozer-js.low-level.instant.waitUntilAvailable", attributes: { "bulldozer.low_level.backend": "instant-availability" } }, async () => {}); + return await traceSpanHot({ description: "bulldozer-js.low-level.instant.waitUntilAvailable", attributes: { "bulldozer.low_level.backend": "instant-availability" } }, async () => {}); }, async waitUntilDurable(seq) { - await traceSpan({ description: "bulldozer-js.low-level.instant.waitUntilDurable", attributes: { "bulldozer.low_level.backend": "instant-availability" } }, async () => await wrapped.waitUntilDurable(await getUnderlyingSeq(seq))); + await traceSpanHot({ description: "bulldozer-js.low-level.instant.waitUntilDurable", attributes: { "bulldozer.low_level.backend": "instant-availability" } }, async () => await wrapped.waitUntilDurable(await getUnderlyingSeq(seq))); }, async waitUntilReplicated(seq) { - await traceSpan({ description: "bulldozer-js.low-level.instant.waitUntilReplicated", attributes: { "bulldozer.low_level.backend": "instant-availability" } }, async () => await wrapped.waitUntilReplicated(await getUnderlyingSeq(seq))); + await traceSpanHot({ description: "bulldozer-js.low-level.instant.waitUntilReplicated", attributes: { "bulldozer.low_level.backend": "instant-availability" } }, async () => await wrapped.waitUntilReplicated(await getUnderlyingSeq(seq))); }, combineSeqs(...seqs) { if (seqs.length === 0) return initialSeq; @@ -266,7 +283,7 @@ export function declareInstantAvailabilityLowLevelDatabase(wrapped: LowLevelData return createSeq((async () => wrapped.combineSeqs(...await Promise.all(seqs.map(async seq => await getUnderlyingSeq(seq)))))()); }, async debugSnapshot() { - return await traceSpan({ description: "bulldozer-js.low-level.instant.debugSnapshot", attributes: { "bulldozer.low_level.backend": "instant-availability" } }, async () => await wrapped.debugSnapshot?.() ?? { stores: {}, dumps: {} }); + return await traceSpanHot({ description: "bulldozer-js.low-level.instant.debugSnapshot", attributes: { "bulldozer.low_level.backend": "instant-availability" } }, async () => await wrapped.debugSnapshot?.() ?? { stores: {}, dumps: {} }); }, debugInstantAvailability() { return { @@ -277,7 +294,7 @@ export function declareInstantAvailabilityLowLevelDatabase(wrapped: LowLevelData }; }, async waitUntilUnderlyingAvailable(seq) { - await traceSpan({ description: "bulldozer-js.low-level.instant.waitUntilUnderlyingAvailable", attributes: { "bulldozer.low_level.backend": "instant-availability" } }, async () => await getSeqRecord(seq).underlyingAvailable); + await traceSpanHot({ description: "bulldozer-js.low-level.instant.waitUntilUnderlyingAvailable", attributes: { "bulldozer.low_level.backend": "instant-availability" } }, async () => await getSeqRecord(seq).underlyingAvailable); }, initialSeq, }; diff --git a/apps/bulldozer-js/src/databases/low-level/implementations/lmdb.test.ts b/apps/bulldozer-js/src/databases/low-level/implementations/lmdb.test.ts index 0d48257cb..5472d6a4c 100644 --- a/apps/bulldozer-js/src/databases/low-level/implementations/lmdb.test.ts +++ b/apps/bulldozer-js/src/databases/low-level/implementations/lmdb.test.ts @@ -99,4 +99,44 @@ describe("LMDB low-level database", () => { await rm(path, { recursive: true, force: true }); } }); + + it("coalesces independent writes into one delayed transaction", async () => { + const path = await tempLmdbPath(); + try { + const db = declareLmdbLowLevelDatabase({ path, dbId: "coalesce" }); + const store = db.declareKvStore("store"); + const beforeVersion = db.getDebugInfo().currentVersion; + + const first = await store.setAll([{ key: buffer("a"), value: buffer("one") }]); + const second = await store.setAll([{ key: buffer("b"), value: buffer("two") }]); + + expect(db.getDebugInfo().currentVersion).toBe(beforeVersion); + await db.waitUntilAvailable(db.combineSeqs(first.seq, second.seq)); + + expect(db.getDebugInfo().currentVersion).toBe(beforeVersion + 1); + expect(text((await store.get(buffer("a"))).buffer)).toBe("one"); + expect(text((await store.get(buffer("b"))).buffer)).toBe("two"); + } finally { + await rm(path, { recursive: true, force: true }); + } + }); + + it("does not deadlock when one queued write requires another queued write", async () => { + const path = await tempLmdbPath(); + try { + const db = declareLmdbLowLevelDatabase({ path, dbId: "same-batch-dependency" }); + const store = db.declareKvStore("store"); + const beforeVersion = db.getDebugInfo().currentVersion; + + const first = await store.setAll([{ key: buffer("parent"), value: buffer("first") }]); + const second = await store.setAll([{ key: buffer("child"), value: buffer("second") }], { requiresSeq: db.combineSeqs(first.seq) }); + + await db.waitUntilAvailable(second.seq); + expect(db.getDebugInfo().currentVersion).toBe(beforeVersion + 1); + expect(text((await store.get(buffer("parent"))).buffer)).toBe("first"); + expect(text((await store.get(buffer("child"))).buffer)).toBe("second"); + } finally { + await rm(path, { recursive: true, force: true }); + } + }); }); diff --git a/apps/bulldozer-js/src/databases/low-level/implementations/lmdb.ts b/apps/bulldozer-js/src/databases/low-level/implementations/lmdb.ts index 60c9699f3..8e249e9c6 100644 --- a/apps/bulldozer-js/src/databases/low-level/implementations/lmdb.ts +++ b/apps/bulldozer-js/src/databases/low-level/implementations/lmdb.ts @@ -1,7 +1,7 @@ import { encodeBase64 } from "@hexclave/shared/dist/utils/bytes"; import { wait } from "@hexclave/shared/dist/utils/promises"; -import { traceSpan } from "../../../otel.js"; import * as lmdb from "lmdb"; +import { traceSpanHot } from "../../../otel.js"; import { DatabaseSeq } from "../../index.js"; import { LowLevelDatabase, LowLevelDatabaseDebugEntry, LowLevelKvDump, LowLevelKvStore } from "../index.js"; @@ -10,6 +10,13 @@ type BinaryDatabase = lmdb.Database; type VersionedBinaryDatabase = BinaryDatabase & { getEntry(key: Buffer): { value: Buffer, version?: number } | undefined, }; +type PendingCommitOperation = { + seqId: string, + requiresSeq: DatabaseSeq, + action: (version: number) => Promise, + resolve: () => void, + reject: (error: unknown) => void, +}; function arrayBuffersAreEqual(a: ArrayBuffer, b: ArrayBuffer): boolean { if (a.byteLength !== b.byteLength) return false; @@ -51,6 +58,75 @@ function validateValue(name: string, value: ArrayBuffer) { if (value.byteLength > 2_000_000_000) throw new Error(`KV store ${name} must be <= 2GB`); } +function createVoidDeferred() { + let resolveOperation: () => void = () => { + throw new Error("Deferred promise resolved before initialization"); + }; + let rejectOperation: (error: unknown) => void = (_error) => { + throw new Error("Deferred promise rejected before initialization"); + }; + const promise = new Promise((resolve, reject) => { + resolveOperation = () => resolve(); + rejectOperation = error => reject(error); + }); + return { promise, resolve: resolveOperation, reject: rejectOperation }; +} + +type LmdbActivityStats = { + puts: number, + putBytes: number, + putAwaitTotalMs: number, + transactions: number, + transactionTotalMs: number, + transactionQueueWaitTotalMs: number, + transactionActionTotalMs: number, + metaPutTotalMs: number, + transactionCommitTailTotalMs: number, + requiredSeqWaits: number, + requiredSeqWaitTotalMs: number, + waitUntilAvailableResolves: number, + waitUntilDurableResolves: number, + waitUntilAvailableResolveTotalMs: number, + waitUntilDurableResolveTotalMs: number, + combinedSeqAvailabilityResolves: number, + combinedSeqDurabilityResolves: number, + combinedSeqAvailabilityResolveTotalMs: number, + combinedSeqDurabilityResolveTotalMs: number, +}; + +function emptyActivityStats(): LmdbActivityStats { + return { + puts: 0, + putBytes: 0, + putAwaitTotalMs: 0, + transactions: 0, + transactionTotalMs: 0, + transactionQueueWaitTotalMs: 0, + transactionActionTotalMs: 0, + metaPutTotalMs: 0, + transactionCommitTailTotalMs: 0, + requiredSeqWaits: 0, + requiredSeqWaitTotalMs: 0, + waitUntilAvailableResolves: 0, + waitUntilDurableResolves: 0, + waitUntilAvailableResolveTotalMs: 0, + waitUntilDurableResolveTotalMs: 0, + combinedSeqAvailabilityResolves: 0, + combinedSeqDurabilityResolves: 0, + combinedSeqAvailabilityResolveTotalMs: 0, + combinedSeqDurabilityResolveTotalMs: 0, + }; +} + +function hasActivity(stats: LmdbActivityStats): boolean { + return stats.puts > 0 + || stats.transactions > 0 + || stats.waitUntilAvailableResolves > 0 + || stats.waitUntilDurableResolves > 0 + || stats.combinedSeqAvailabilityResolves > 0 + || stats.combinedSeqDurabilityResolves > 0; +} + export function declareLmdbLowLevelDatabase(options: { path: string, dbId?: string, simulateReadMissDelayMs?: number }): LowLevelDatabase { const dbId = options.dbId ?? "default"; const simulateReadMissDelayMs = options.simulateReadMissDelayMs ?? 0; @@ -62,6 +138,55 @@ export function declareLmdbLowLevelDatabase(options: { path: string, dbId?: stri const debugEntriesByStoreId = new Map<`${"store" | "dump"}-${string}`, () => Promise>(); const seqToAvailability = new Map>(); const seqToDurability = new Map>(); + const combinedSeqToAvailability = new Map>(); + const combinedSeqToDurability = new Map>(); + const combinedSeqDependencies = new Map(); + let pendingCommitOperations: PendingCommitOperation[] = []; + let pendingCommitFlushTimer: ReturnType | null = null; + let pendingCommitFlushPromise: Promise | null = null; + let activityStats = emptyActivityStats(); + let activityWindowStartedAt = performance.now(); + const activityInterval = setInterval(() => { + if (!hasActivity(activityStats)) return; + const now = performance.now(); + const elapsedMs = now - activityWindowStartedAt; + const elapsedSeconds = elapsedMs / 1000; + console.debug("bulldozer-js low-level lmdb activity", { + dbId, + elapsedMs, + putsPerSecond: activityStats.puts / elapsedSeconds, + averagePutBytes: activityStats.puts === 0 ? 0 : activityStats.putBytes / activityStats.puts, + averagePutAwaitMs: activityStats.puts === 0 ? 0 : activityStats.putAwaitTotalMs / activityStats.puts, + transactionsPerSecond: activityStats.transactions / elapsedSeconds, + averageTransactionMs: activityStats.transactions === 0 ? 0 : activityStats.transactionTotalMs / activityStats.transactions, + averageTransactionQueueWaitMs: activityStats.transactions === 0 ? 0 : activityStats.transactionQueueWaitTotalMs / activityStats.transactions, + averageTransactionActionMs: activityStats.transactions === 0 ? 0 : activityStats.transactionActionTotalMs / activityStats.transactions, + averageMetaPutMs: activityStats.transactions === 0 ? 0 : activityStats.metaPutTotalMs / activityStats.transactions, + averageTransactionCommitTailMs: activityStats.transactions === 0 ? 0 : activityStats.transactionCommitTailTotalMs / activityStats.transactions, + requiredSeqWaitsPerSecond: activityStats.requiredSeqWaits / elapsedSeconds, + averageRequiredSeqWaitMs: activityStats.requiredSeqWaits === 0 ? 0 : activityStats.requiredSeqWaitTotalMs / activityStats.requiredSeqWaits, + waitUntilAvailableResolvesPerSecond: activityStats.waitUntilAvailableResolves / elapsedSeconds, + waitUntilDurableResolvesPerSecond: activityStats.waitUntilDurableResolves / elapsedSeconds, + averageSeqToAvailabilityResolveMs: activityStats.waitUntilAvailableResolves === 0 ? 0 : activityStats.waitUntilAvailableResolveTotalMs / activityStats.waitUntilAvailableResolves, + averageSeqToDurabilityResolveMs: activityStats.waitUntilDurableResolves === 0 ? 0 : activityStats.waitUntilDurableResolveTotalMs / activityStats.waitUntilDurableResolves, + combinedSeqAvailabilityResolvesPerSecond: activityStats.combinedSeqAvailabilityResolves / elapsedSeconds, + combinedSeqDurabilityResolvesPerSecond: activityStats.combinedSeqDurabilityResolves / elapsedSeconds, + averageCombinedSeqAvailabilityResolveMs: activityStats.combinedSeqAvailabilityResolves === 0 ? 0 : activityStats.combinedSeqAvailabilityResolveTotalMs / activityStats.combinedSeqAvailabilityResolves, + averageCombinedSeqDurabilityResolveMs: activityStats.combinedSeqDurabilityResolves === 0 ? 0 : activityStats.combinedSeqDurabilityResolveTotalMs / activityStats.combinedSeqDurabilityResolves, + mapSizes: { + seqToAvailability: seqToAvailability.size, + seqToDurability: seqToDurability.size, + combinedSeqToAvailability: combinedSeqToAvailability.size, + combinedSeqToDurability: combinedSeqToDurability.size, + combinedSeqDependencies: combinedSeqDependencies.size, + debugEntriesByStoreId: debugEntriesByStoreId.size, + }, + currentVersion, + }); + activityStats = emptyActivityStats(); + activityWindowStartedAt = now; + }, 5_000); + activityInterval.unref(); const initialSeq = [dbId, initialSeqId] as unknown as LmdbSeq; const toSeq = (seqId: string) => [dbId, seqId] as unknown as LmdbSeq; @@ -73,40 +198,119 @@ export function declareLmdbLowLevelDatabase(options: { path: string, dbId?: stri return seq[1]; }; const getAvailabilityPromise = (seqId: string) => { - return seqToAvailability.get(seqId) ?? Promise.resolve(); + return seqToAvailability.get(seqId) ?? combinedSeqToAvailability.get(seqId) ?? Promise.resolve(); }; const getDurabilityPromise = (seqId: string) => { - return seqToDurability.get(seqId) ?? Promise.resolve(); + return seqToDurability.get(seqId) ?? combinedSeqToDurability.get(seqId) ?? Promise.resolve(); }; const rememberAvailability = (seqId: string, promise: Promise) => { - const availability = traceSpan({ description: "bulldozer-js.low-level.lmdb.availability", attributes: { "bulldozer.low_level.backend": "lmdb" } }, async () => await promise.then(() => { + const insertedAt = performance.now(); + const availability = traceSpanHot({ description: "bulldozer-js.low-level.lmdb.availability", attributes: { "bulldozer.low_level.backend": "lmdb" } }, async () => await promise.then(() => { + activityStats.waitUntilAvailableResolveTotalMs += performance.now() - insertedAt; + activityStats.waitUntilAvailableResolves++; seqToAvailability.delete(seqId); })); availability.catch(() => {}); seqToAvailability.set(seqId, availability); }; const rememberDurability = (seqId: string, promise: Promise) => { - const durability = traceSpan({ description: "bulldozer-js.low-level.lmdb.durability", attributes: { "bulldozer.low_level.backend": "lmdb" } }, async () => await promise.then(async () => await root.flushed).then(() => { + const insertedAt = performance.now(); + const durability = traceSpanHot({ description: "bulldozer-js.low-level.lmdb.durability", attributes: { "bulldozer.low_level.backend": "lmdb" } }, async () => await promise.then(async () => await root.flushed).then(() => { + activityStats.waitUntilDurableResolveTotalMs += performance.now() - insertedAt; + activityStats.waitUntilDurableResolves++; seqToDurability.delete(seqId); })); durability.catch(() => {}); seqToDurability.set(seqId, durability); }; + const rememberCombinedAvailability = (seqId: string, promise: Promise) => { + const insertedAt = performance.now(); + const availability = traceSpanHot({ description: "bulldozer-js.low-level.lmdb.combinedAvailability", attributes: { "bulldozer.low_level.backend": "lmdb" } }, async () => await promise.then(() => { + activityStats.combinedSeqAvailabilityResolveTotalMs += performance.now() - insertedAt; + activityStats.combinedSeqAvailabilityResolves++; + combinedSeqToAvailability.delete(seqId); + combinedSeqDependencies.delete(seqId); + })); + availability.catch(() => {}); + combinedSeqToAvailability.set(seqId, availability); + }; + const rememberCombinedDurability = (seqId: string, promise: Promise) => { + const insertedAt = performance.now(); + const durability = traceSpanHot({ description: "bulldozer-js.low-level.lmdb.combinedDurability", attributes: { "bulldozer.low_level.backend": "lmdb" } }, async () => await promise.then(() => { + activityStats.combinedSeqDurabilityResolveTotalMs += performance.now() - insertedAt; + activityStats.combinedSeqDurabilityResolves++; + combinedSeqToDurability.delete(seqId); + })); + durability.catch(() => {}); + combinedSeqToDurability.set(seqId, durability); + }; const trackCommit = (seqId: string, promise: Promise) => { rememberAvailability(seqId, promise); rememberDurability(seqId, promise); return toSeq(seqId); }; + const commitBatch = async (operations: PendingCommitOperation[]) => { + if (operations.length === 0) return; + try { + const version = nextVersion(); + await traceSpanHot({ description: "bulldozer-js.low-level.lmdb.commit", attributes: { "bulldozer.low_level.backend": "lmdb", "bulldozer.low_level.operation_count": operations.length } }, async () => { + const requiredSeqWaitStartedAt = performance.now(); + const batchSeqIds = new Set(operations.map(operation => operation.seqId)); + await Promise.all(operations.map(async operation => await waitUntilAvailableOutsideBatch(operation.requiresSeq, batchSeqIds))); + activityStats.requiredSeqWaits++; + activityStats.requiredSeqWaitTotalMs += performance.now() - requiredSeqWaitStartedAt; + const transactionStartedAt = performance.now(); + let transactionCallbackFinishedAt: number | null = null; + await root.transaction(() => { + activityStats.transactionQueueWaitTotalMs += performance.now() - transactionStartedAt; + activityStats.transactions++; + return (async () => { + const actionStartedAt = performance.now(); + for (const operation of operations) await operation.action(version); + activityStats.transactionActionTotalMs += performance.now() - actionStartedAt; + const metaPutStartedAt = performance.now(); + await meta.put("seq", version); + activityStats.metaPutTotalMs += performance.now() - metaPutStartedAt; + })().finally(() => { + transactionCallbackFinishedAt = performance.now(); + }); + }).finally(() => { + const transactionFinishedAt = performance.now(); + activityStats.transactionTotalMs += transactionFinishedAt - transactionStartedAt; + if (transactionCallbackFinishedAt !== null) activityStats.transactionCommitTailTotalMs += transactionFinishedAt - transactionCallbackFinishedAt; + }); + }); + for (const operation of operations) operation.resolve(); + } catch (error) { + for (const operation of operations) operation.reject(error); + throw error; + } + }; + const flushPendingCommits = async () => { + if (pendingCommitFlushTimer !== null) { + clearTimeout(pendingCommitFlushTimer); + pendingCommitFlushTimer = null; + } + const batch = pendingCommitOperations; + pendingCommitOperations = []; + await commitBatch(batch); + }; + const schedulePendingCommitFlush = () => { + if (pendingCommitFlushTimer !== null) return; + pendingCommitFlushTimer = setTimeout(() => { + pendingCommitFlushTimer = null; + pendingCommitFlushPromise = flushPendingCommits().finally(() => { + pendingCommitFlushPromise = null; + }); + pendingCommitFlushPromise.catch(() => {}); + }, 10); + }; const commit = (requiresSeq: DatabaseSeq, action: (version: number) => Promise) => { - const version = nextVersion(); const seqId = nextSeqId(); - const promise = traceSpan({ description: "bulldozer-js.low-level.lmdb.commit", attributes: { "bulldozer.low_level.backend": "lmdb" } }, async () => await waitUntilAvailable(requiresSeq).then(async () => await root.transaction(() => { - return (async () => { - await action(version); - await meta.put("seq", version); - })(); - }))); - return trackCommit(seqId, promise); + const deferred = createVoidDeferred(); + pendingCommitOperations.push({ seqId, requiresSeq, action, resolve: deferred.resolve, reject: deferred.reject }); + schedulePendingCommitFlush(); + return trackCommit(seqId, deferred.promise); }; const commitIfVersion = async (db: BinaryDatabase, key: Buffer, version: number, action: (version: number) => Promise) => { const nextVersionRef: { value: number | null } = { value: null }; @@ -124,18 +328,37 @@ export function declareLmdbLowLevelDatabase(options: { path: string, dbId?: stri rememberDurability(seqId, Promise.resolve()); return toSeq(seqId); }; - const dumpKeyForVersion = (version: number, index: number) => { - const key = crypto.getRandomValues(new Uint8Array(48)); - new DataView(key.buffer).setBigUint64(0, BigInt(version)); - new DataView(key.buffer).setUint32(8, index); - return key.buffer; - }; + const dumpKey = () => crypto.getRandomValues(new Uint8Array(48)).buffer; const putWithVersion = async (db: BinaryDatabase, key: Buffer, value: Buffer, version: number) => { - await db.put(key, value, version); + activityStats.puts++; + activityStats.putBytes += value.byteLength; + const startedAt = performance.now(); + try { + await db.put(key, value, version); + } finally { + activityStats.putAwaitTotalMs += performance.now() - startedAt; + } }; const waitUntilAvailable = async (seq: DatabaseSeq) => { await getAvailabilityPromise(getSeqId(seq)); }; + const waitUntilDurable = async (seq: DatabaseSeq) => { + await getDurabilityPromise(getSeqId(seq)); + }; + const waitUntilAvailableOutsideBatch = async (seq: DatabaseSeq, batchSeqIds: Set): Promise => { + const seqId = getSeqId(seq); + if (seqId === initialSeqId || batchSeqIds.has(seqId)) return; + const dependencies = combinedSeqDependencies.get(seqId); + if (dependencies === undefined) { + await getAvailabilityPromise(seqId); + return; + } + await Promise.all(dependencies.map(async dependencySeqId => { + if (dependencySeqId === initialSeqId || batchSeqIds.has(dependencySeqId)) return; + const dependencySeq = toSeq(dependencySeqId); + await waitUntilAvailableOutsideBatch(dependencySeq, batchSeqIds); + })); + }; const waitUntilAllAvailable = async () => { await Promise.all(seqToAvailability.values()); }; @@ -152,7 +375,7 @@ export function declareLmdbLowLevelDatabase(options: { path: string, dbId?: stri const result: LowLevelKvStore & LowLevelKvDump = { async get(key) { - return await traceSpan({ description: "bulldozer-js.low-level.lmdb.get", attributes }, async () => { + return await traceSpanHot({ description: "bulldozer-js.low-level.lmdb.get", attributes }, async () => { validateKey(key); if (simulateReadMissDelayMs > 0) await wait(simulateReadMissDelayMs); const [buffer] = await db.getMany([bufferFromArrayBuffer(key)]); @@ -163,7 +386,7 @@ export function declareLmdbLowLevelDatabase(options: { path: string, dbId?: stri }); }, async setAll(entries, setOptions) { - return await traceSpan({ description: "bulldozer-js.low-level.lmdb.setAll", attributes: { ...attributes, "bulldozer.low_level.entry_count": entries.length } }, async () => { + return await traceSpanHot({ description: "bulldozer-js.low-level.lmdb.setAll", attributes: { ...attributes, "bulldozer.low_level.entry_count": entries.length } }, async () => { for (const { key, value } of entries) { validateKey(key); validateValue("value", value); @@ -179,7 +402,7 @@ export function declareLmdbLowLevelDatabase(options: { path: string, dbId?: stri }); }, async deleteAll(keys) { - return await traceSpan({ description: "bulldozer-js.low-level.lmdb.deleteAll", attributes: { ...attributes, "bulldozer.low_level.key_count": keys.length } }, async () => { + return await traceSpanHot({ description: "bulldozer-js.low-level.lmdb.deleteAll", attributes: { ...attributes, "bulldozer.low_level.key_count": keys.length } }, async () => { for (const key of keys) validateKey(key); if (keys.length === 0) return { seq: initialSeq }; return { @@ -190,25 +413,20 @@ export function declareLmdbLowLevelDatabase(options: { path: string, dbId?: stri }); }, async insertAll(values, insertOptions) { - return await traceSpan({ description: "bulldozer-js.low-level.lmdb.insertAll", attributes: { ...attributes, "bulldozer.low_level.value_count": values.length } }, async () => { + return await traceSpanHot({ description: "bulldozer-js.low-level.lmdb.insertAll", attributes: { ...attributes, "bulldozer.low_level.value_count": values.length } }, async () => { for (const value of values) validateValue("value", value); if (values.length === 0) return { keys: [], seq: insertOptions?.requiresSeq ?? initialSeq }; - const version = nextVersion(); - const seqId = nextSeqId(); - const keys = values.map((_, index) => dumpKeyForVersion(version, index)); - const promise = traceSpan({ description: "bulldozer-js.low-level.lmdb.insertAll.commit", attributes }, async () => await waitUntilAvailable(insertOptions?.requiresSeq ?? initialSeq).then(async () => await root.transaction(() => { - return (async () => { - for (let i = 0; i < values.length; i++) { - await putWithVersion(db, bufferFromArrayBuffer(keys[i]), bufferFromArrayBuffer(values[i]), version); - } - await meta.put("seq", version); - })(); - }))); - return { keys, seq: trackCommit(seqId, promise) }; + const keys = values.map(() => dumpKey()); + return { + keys, + seq: commit(insertOptions?.requiresSeq ?? initialSeq, async version => { + await Promise.all(values.map(async (value, index) => await putWithVersion(db, bufferFromArrayBuffer(keys[index]), bufferFromArrayBuffer(value), version))); + }), + }; }); }, async compareAndSet(key, compare, value, casOptions) { - return await traceSpan({ description: "bulldozer-js.low-level.lmdb.compareAndSet", attributes }, async () => { + return await traceSpanHot({ description: "bulldozer-js.low-level.lmdb.compareAndSet", attributes }, async () => { validateKey(key); validateValue("compare", compare); validateValue("value", value); @@ -224,7 +442,7 @@ export function declareLmdbLowLevelDatabase(options: { path: string, dbId?: stri }); }, async debugEntries() { - return await traceSpan({ description: "bulldozer-js.low-level.lmdb.debugEntries", attributes }, async () => await (db.getRange() as lmdb.RangeIterable<{ key: Uint8Array, value: Buffer }>).map(({ key, value }) => { + return await traceSpanHot({ description: "bulldozer-js.low-level.lmdb.debugEntries", attributes }, async () => await (db.getRange() as lmdb.RangeIterable<{ key: Uint8Array, value: Buffer }>).map(({ key, value }) => { const keyBuffer = Buffer.from(key); const valueBuffer = Buffer.from(value); return { @@ -243,6 +461,27 @@ export function declareLmdbLowLevelDatabase(options: { path: string, dbId?: stri }; return { + getDebugInfo() { + return { + backend: "lmdb", + constructorArguments: options, + dbId, + simulateReadMissDelayMs, + root, + meta, + currentVersion, + debugEntriesByStoreId, + seqToAvailability, + seqToDurability, + combinedSeqToAvailability, + combinedSeqToDurability, + combinedSeqDependencies, + pendingCommitOperations, + pendingCommitFlushTimer, + pendingCommitFlushPromise, + initialSeq, + }; + }, declareKvDump(dumpId) { return declareLmdbLowLevelKvStoreOrDump("dump", dumpId); }, @@ -250,26 +489,28 @@ export function declareLmdbLowLevelDatabase(options: { path: string, dbId?: stri return declareLmdbLowLevelKvStoreOrDump("store", storeId); }, async waitUntilAvailable(seq) { - await traceSpan({ description: "bulldozer-js.low-level.lmdb.waitUntilAvailable", attributes: { "bulldozer.low_level.backend": "lmdb" } }, async () => await waitUntilAvailable(seq)); + await traceSpanHot({ description: "bulldozer-js.low-level.lmdb.waitUntilAvailable", attributes: { "bulldozer.low_level.backend": "lmdb" } }, async () => await waitUntilAvailable(seq)); }, async waitUntilDurable(seq) { - await traceSpan({ description: "bulldozer-js.low-level.lmdb.waitUntilDurable", attributes: { "bulldozer.low_level.backend": "lmdb" } }, async () => await getDurabilityPromise(getSeqId(seq))); + await traceSpanHot({ description: "bulldozer-js.low-level.lmdb.waitUntilDurable", attributes: { "bulldozer.low_level.backend": "lmdb" } }, async () => await waitUntilDurable(seq)); }, async waitUntilReplicated(seq) { - await traceSpan({ description: "bulldozer-js.low-level.lmdb.waitUntilReplicated", attributes: { "bulldozer.low_level.backend": "lmdb" } }, async () => { + await traceSpanHot({ description: "bulldozer-js.low-level.lmdb.waitUntilReplicated", attributes: { "bulldozer.low_level.backend": "lmdb" } }, async () => { await this.waitUntilAvailable(seq); await this.waitUntilDurable(seq); }); }, combineSeqs(...seqs) { if (seqs.length === 0) return initialSeq; + if (seqs.length === 1) return seqs[0]; const seqId = nextSeqId(); - rememberAvailability(seqId, Promise.all(seqs.map(seq => getAvailabilityPromise(getSeqId(seq))))); - rememberDurability(seqId, Promise.all(seqs.map(seq => getDurabilityPromise(getSeqId(seq))))); + combinedSeqDependencies.set(seqId, seqs.map(seq => getSeqId(seq))); + rememberCombinedAvailability(seqId, Promise.all(seqs.map(seq => getAvailabilityPromise(getSeqId(seq))))); + rememberCombinedDurability(seqId, Promise.all(seqs.map(seq => getDurabilityPromise(getSeqId(seq))))); return toSeq(seqId); }, async debugSnapshot() { - return await traceSpan({ description: "bulldozer-js.low-level.lmdb.debugSnapshot", attributes: { "bulldozer.low_level.backend": "lmdb" } }, async () => { + return await traceSpanHot({ description: "bulldozer-js.low-level.lmdb.debugSnapshot", attributes: { "bulldozer.low_level.backend": "lmdb" } }, async () => { const stores: Record = {}; const dumps: Record = {}; for (const [storeId, entries] of debugEntriesByStoreId.entries()) { diff --git a/apps/bulldozer-js/src/databases/piledriver/data-structures/augmented-tree-map.test.ts b/apps/bulldozer-js/src/databases/piledriver/data-structures/augmented-tree-map.test.ts index b2f20e747..1ffcc3a8e 100644 --- a/apps/bulldozer-js/src/databases/piledriver/data-structures/augmented-tree-map.test.ts +++ b/apps/bulldozer-js/src/databases/piledriver/data-structures/augmented-tree-map.test.ts @@ -162,6 +162,34 @@ function withHeapCounters(tree: AugmentedTreeMap, arity }; } +function withMultiMapHeapCounters(tree: AugmentedTreeMultiMap, multiMapOptions: ConstructorParameters>[0]) { + let gets = 0; + const seen = new WeakMap(); + + const wrapRef = (ref: PiledriverHeapObject): PiledriverHeapObject => { + const cached = seen.get(ref); + if (cached) return cached; + const wrapped = { + async get() { + gets++; + const node: any = await ref.get(); + return isNode(node) ? { ...node, children: node.children.map(wrapChild) } : node; + }, + [isPiledriverHeapObjectSymbol]: true as const, + } as PiledriverHeapObject; + seen.set(ref, wrapped); + return wrapped; + }; + const wrapChild = (child: any) => child ? { ...child, ref: wrapRef(child.ref) } : child; + const serialized = tree.toPiledriverObject() as { type: string, tree: { type: string, root: any } }; + + return { + tree: AugmentedTreeMultiMap.fromPiledriverObject({ ...serialized, tree: { ...serialized.tree, root: wrapChild(serialized.tree.root) } }, multiMapOptions), + reset: () => { gets = 0; }, + gets: () => gets, + }; +} + async function collectRefs(tree: AugmentedTreeMap) { const refs = new Set(); const visit = async (child: Serialized["root"]) => { @@ -295,6 +323,54 @@ describe("AugmentedTreeMap", () => { expect(await arrayFrom(tree.entries())).toEqual([[10, "b", 2], [11, "a", 4]]); }); + it("answers hasAny without materializing all entries for a key", async () => { + const multiMapOptions = { + ...options(8), + entryIdComparator: stringCompare, + }; + let tree = new AugmentedTreeMultiMap(multiMapOptions); + + expect(await tree.hasAny(10)).toBe(false); + for (let i = 0; i < 1000; i++) tree = await tree.add(10, `id-${i}`, i); + tree = await tree.add(11, "a", 1); + + expect(await tree.hasAny(10)).toBe(true); + expect(await tree.hasAny(11)).toBe(true); + expect(await tree.hasAny(12)).toBe(false); + + // hasAny must stay O(depth) even when many entries share the key; getAll here would load + // all 1000 entries (hundreds of node reads). + const counted = withMultiMapHeapCounters(tree, multiMapOptions); + counted.reset(); + await counted.tree.hasAny(10); + expect(counted.gets()).toBeLessThanOrEqual(8); + }); + + it("uses binary search for bounded range scans inside large nodes", async () => { + let comparisons = 0; + const countedOptions = { + arity: 2048, + comparator: (a: number, b: number) => { + comparisons++; + return a - b; + }, + initialAugmentation: 0, + extractAugmentation: (value: number) => value, + mergeAugmentations: (...values: number[]) => values.reduce((sum, value) => sum + value, 0), + entryIdComparator: stringCompare, + }; + let tree = new AugmentedTreeMultiMap(countedOptions); + for (let i = 0; i < 1000; i++) tree = await tree.add(i, "", i); + + comparisons = 0; + expect(await arrayFrom(tree.entries({ gte: 990, limit: 1 }))).toEqual([[990, "", 990]]); + expect(comparisons).toBeLessThan(80); + + comparisons = 0; + expect(await arrayFrom(tree.entries({ lte: 10, reverse: true, limit: 1 }))).toEqual([[10, "", 10]]); + expect(comparisons).toBeLessThan(80); + }); + it("keeps heap reads logarithmic for point operations", async () => { for (const size of [100, 1_000, 10_000]) { const counted = withHeapCounters(await build(size)); diff --git a/apps/bulldozer-js/src/databases/piledriver/data-structures/augmented-tree-map.ts b/apps/bulldozer-js/src/databases/piledriver/data-structures/augmented-tree-map.ts index 0fa07cfb9..6177fb0da 100644 --- a/apps/bulldozer-js/src/databases/piledriver/data-structures/augmented-tree-map.ts +++ b/apps/bulldozer-js/src/databases/piledriver/data-structures/augmented-tree-map.ts @@ -26,10 +26,11 @@ const noAugmentation = Symbol("no-augmentation"); type NoAugmentation = typeof noAugmentation; type Entry = [K, V]; type Child = { ref: PiledriverHeapObject, augmentation: A, size: number, entryCount: number, minKey: K, maxKey: K }; -type Split = { entry: Entry, right: Child }; +type StoredValue = V | PiledriverHeapObject; +type Split = { entry: Entry>, right: Child }; // Persisted B-tree node. Children are heap objects, so unchanged subtrees are shared across versions. -type Node = { - entries: Entry[], +type Node = { + entries: Entry>[], children: Child[], augmentation: A, size: number, @@ -104,6 +105,15 @@ export class AugmentedTreeMultiMap { + for await (const _entry of this.entries({ gte: key, lte: key, limit: 1 })) return true; + return false; + } + async add(key: Key, entryId: EntryId, value: Value) { return await this.insertRaw({ key, id: entryId }, value); } @@ -176,7 +186,7 @@ export class AugmentedTreeMultiMap): Promise { for (let node = await this.node(this.root?.ref ?? null); node;) { const { index, found } = this.search(node.entries, key); - if (found) return node.entries[index][1]; + if (found) return await this.loadValue(node.entries[index][1]); node = await this.node(node.children[index]?.ref ?? null); } } @@ -196,6 +206,8 @@ export class AugmentedTreeMultiMap> = {}): AsyncIterable<[MultiKey, Value]> { let yielded = 0; + const lowerBound = this.tighterLowerBound(options.gte, options.gt); + const upperBound = this.tighterUpperBound(options.lte, options.lt); const isInRange = (key: MultiKey) => (options.gte === undefined || this.compareKeys(key, options.gte) >= 0) && (options.gt === undefined || this.compareKeys(key, options.gt) > 0) @@ -206,22 +218,25 @@ export class AugmentedTreeMultiMap= options.limit) || !tree.overlaps(child, options)) return; const node = (await tree.node(child.ref))!; - const visitEntry = function* (entry: Entry, Value>): Iterable, Value>> { - if (isInRange(entry[0]) && (options.limit === undefined || yielded++ < options.limit)) yield entry; + const visitEntry = async function* (entry: Entry, StoredValue>): AsyncIterable, Value>> { + if (isInRange(entry[0]) && (options.limit === undefined || yielded++ < options.limit)) yield [entry[0], await tree.loadValue(entry[1])]; }; + const startIndex = lowerBound === undefined ? 0 : tree.lowerBoundIndex(node.entries, lowerBound); + const endIndex = upperBound === undefined ? node.entries.length : tree.lowerBoundIndex(node.entries, upperBound); + if (options.reverse) { - for (let i = node.entries.length - 1; i >= 0; i--) { - yield* walk(tree, node.children[i + 1] ?? null); + yield* walk(tree, node.children[endIndex] ?? null); + for (let i = endIndex - 1; i >= startIndex; i--) { yield* visitEntry(node.entries[i]); + yield* walk(tree, node.children[i] ?? null); } - yield* walk(tree, node.children[0] ?? null); } else { - for (let i = 0; i < node.entries.length; i++) { + for (let i = startIndex; i < endIndex; i++) { yield* walk(tree, node.children[i] ?? null); yield* visitEntry(node.entries[i]); } - yield* walk(tree, node.children[node.entries.length] ?? null); + yield* walk(tree, node.children[endIndex] ?? null); } }; @@ -246,6 +261,14 @@ export class AugmentedTreeMultiMap, Value, Augmentation> : null; } + private storeValue(value: Value): StoredValue { + return value !== null && typeof value === "object" ? asHeapObject(value) : value; + } + + private async loadValue(value: StoredValue): Promise { + return value !== null && typeof value === "object" && isPiledriverHeapObjectSymbol in value ? await value.get() as Value : value; + } + private async empty() { return this.options.initialAugmentation !== undefined ? this.options.initialAugmentation : await this.options.mergeAugmentations(); } @@ -268,7 +291,7 @@ export class AugmentedTreeMultiMap, Value>[], children: Child, Augmentation>[] = []) { + private async make(entries: Entry, StoredValue>[], children: Child, Augmentation>[] = []) { if (!entries.length && children.length !== 1) throw new Error("Invalid empty B-tree node"); if (!entries.length) { const [onlyChild] = children; @@ -292,7 +315,7 @@ export class AugmentedTreeMultiMap, Value>[], key: MultiKey) { + private search(entries: Entry, StoredValue>[], key: MultiKey) { + const low = this.lowerBoundIndex(entries, key); + return { index: low, found: low < entries.length && this.compareKeys(entries[low][0], key) === 0 }; + } + + private lowerBoundIndex(entries: Entry, StoredValue>[], key: MultiKey) { let low = 0, high = entries.length; while (low < high) { const mid = (low + high) >> 1; if (this.compareKeys(entries[mid][0], key) < 0) low = mid + 1; else high = mid; } - return { index: low, found: low < entries.length && this.compareKeys(entries[low][0], key) === 0 }; + return low; + } + + private tighterLowerBound(a: MultiKey | undefined, b: MultiKey | undefined) { + if (a === undefined) return b; + if (b === undefined) return a; + return this.compareKeys(a, b) >= 0 ? a : b; + } + + private tighterUpperBound(a: MultiKey | undefined, b: MultiKey | undefined) { + if (a === undefined) return b; + if (b === undefined) return a; + return this.compareKeys(a, b) <= 0 ? a : b; } private async finishUpsert(result: { root: Child, Augmentation>, split?: Split, Value, Augmentation> }) { return result.split ? await this.make([result.split.entry], [result.root, result.split.right]) : result.root; } - private async split(entries: Entry, Value>[], children: Child, Augmentation>[]) { + private async split(entries: Entry, StoredValue>[], children: Child, Augmentation>[]) { const middle = entries.length >> 1; const left = await this.make(entries.slice(0, middle), children.length ? children.slice(0, middle + 1) : []); const right = await this.make(entries.slice(middle + 1), children.length ? children.slice(middle + 1) : []); return { root: left, split: { entry: entries[middle], right } }; } - private async done(entries: Entry, Value>[], children: Child, Augmentation>[], added: boolean) { + private async done(entries: Entry, StoredValue>[], children: Child, Augmentation>[], added: boolean) { const result = entries.length > this.maxEntries() ? await this.split(entries, children) : { root: await this.make(entries, children) }; return { ...result, added }; } private async upsert(heapObject: PiledriverHeapObject | null, key: MultiKey, value: Value, replace: boolean): Promise<{ root: Child, Augmentation>, split?: Split, Value, Augmentation>, added: boolean }> { const node = await this.node(heapObject); - if (!node) return { root: await this.make([[key, value]]), added: true }; + if (!node) return { root: await this.make([[key, this.storeValue(value)]]), added: true }; const { index, found } = this.search(node.entries, key); const entries = [...node.entries]; @@ -359,12 +399,12 @@ export class AugmentedTreeMultiMap, Augmentation>): Promise<{ root: Child, Augmentation> | null, entry: Entry, Value> }> { + private async deleteMin(child: Child, Augmentation>): Promise<{ root: Child, Augmentation> | null, entry: Entry, StoredValue> }> { const node = (await this.node(child.ref))!; const entries = [...node.entries]; const children = [...node.children] as (Child, Augmentation> | null)[]; @@ -432,7 +472,7 @@ export class AugmentedTreeMultiMap, Augmentation>): Promise<{ root: Child, Augmentation> | null, entry: Entry, Value> }> { + private async deleteMax(child: Child, Augmentation>): Promise<{ root: Child, Augmentation> | null, entry: Entry, StoredValue> }> { const node = (await this.node(child.ref))!; const entries = [...node.entries]; const children = [...node.children] as (Child, Augmentation> | null)[]; @@ -448,13 +488,13 @@ export class AugmentedTreeMultiMap, Value>[], children: (Child, Augmentation> | null)[], isRoot: boolean, deleted: boolean) { + private async afterDelete(entries: Entry, StoredValue>[], children: (Child, Augmentation> | null)[], isRoot: boolean, deleted: boolean) { const liveChildren = children.filter(child => child !== null); if (!entries.length) return { root: isRoot ? liveChildren[0] ?? null : liveChildren[0] ? await this.make([], [liveChildren[0]]) : null, deleted }; return { root: await this.make(entries, liveChildren), deleted }; } - private async fixChild(entries: Entry, Value>[], children: (Child, Augmentation> | null)[], index: number, isRoot: boolean): Promise<{ root: Child, Augmentation> | null, deleted: boolean }> { + private async fixChild(entries: Entry, StoredValue>[], children: (Child, Augmentation> | null)[], index: number, isRoot: boolean): Promise<{ root: Child, Augmentation> | null, deleted: boolean }> { const child = children[index]; if (child && child.entryCount >= this.minEntries()) return await this.afterDelete(entries, children, isRoot, true); @@ -491,7 +531,7 @@ export class AugmentedTreeMultiMap, Augmentation> | null, entry: Entry, Value>, right: Child, Augmentation> | null) { + private async mergeChildren(left: Child, Augmentation> | null, entry: Entry, StoredValue>, right: Child, Augmentation> | null) { const leftNode = left ? (await this.node(left.ref))! : { entries: [], children: [] }; const rightNode = right ? (await this.node(right.ref))! : { entries: [], children: [] }; return await this.make( @@ -518,7 +558,7 @@ export class AugmentedTreeMultiMap(); /** @@ -66,15 +69,177 @@ export type PiledriverDatabaseOptions = { disableHeapReadCache?: boolean, }; -// Tracks the chain of objects currently being serialized, so cycles fail fast with a clear -// error instead of hanging (a heap cycle would deadlock on its own memoized promise, and a -// plain object cycle would recurse forever). Sibling/DAG sharing is fine: only true ancestors -// are in the path. -type SerializationPath = { - objects: ReadonlySet, - heapObjects: ReadonlySet, +// Tracks the chain of *heap objects* currently being serialized, so heap cycles fail fast with +// a clear error instead of deadlocking on their own memoized promise. Sibling/DAG sharing is +// fine: only true ancestors are in the path. Plain-object cycles are detected separately with a +// push/pop set during the synchronous payload walk. +type HeapSerializationPath = ReadonlySet; +type PiledriverSerializationTimingStats = { + primitiveNodes: number, + arrayNodes: number, + arrayItems: number, + objectNodes: number, + objectEntries: number, + heapReferenceNodes: number, + serializeToJsonableTotalMs: number, + jsonStringifyTotalMs: number, + textEncodeTotalMs: number, + heapObjectCacheHits: number, + heapObjectCacheMisses: number, + heapObjectCacheHitAwaitTotalMs: number, + heapObjectCacheMissAwaitTotalMs: number, + heapObjectGetTotalMs: number, + heapObjectSerializeTotalMs: number, + heapObjectInsertAwaitTotalMs: number, + branchStats: Map, + heapObjectCacheMissesByShape: Map, + heapObjectCacheMissInlineNodeCountsByShape: Map, }; -const emptySerializationPath: SerializationPath = { objects: new Set(), heapObjects: new Set() }; +type PiledriverSerializationBranchStats = { + primitiveNodes: number, + arrayNodes: number, + objectNodes: number, + objectEntries: number, + heapReferenceNodes: number, + heapObjectCacheHits: number, + heapObjectCacheMisses: number, + heapObjectCacheMissesByShape: Map, + heapObjectCacheMissInlineNodeCountsByShape: Map, +}; +type PiledriverInlineNodeCounts = { + primitiveNodes: number, + arrayNodes: number, + objectNodes: number, + heapReferenceNodes: number, +}; + +function emptyPiledriverSerializationBranchStats(): PiledriverSerializationBranchStats { + return { + primitiveNodes: 0, + arrayNodes: 0, + objectNodes: 0, + objectEntries: 0, + heapReferenceNodes: 0, + heapObjectCacheHits: 0, + heapObjectCacheMisses: 0, + heapObjectCacheMissesByShape: new Map(), + heapObjectCacheMissInlineNodeCountsByShape: new Map(), + }; +} + +function emptyPiledriverSerializationTimingStats(): PiledriverSerializationTimingStats { + return { + primitiveNodes: 0, + arrayNodes: 0, + arrayItems: 0, + objectNodes: 0, + objectEntries: 0, + heapReferenceNodes: 0, + serializeToJsonableTotalMs: 0, + jsonStringifyTotalMs: 0, + textEncodeTotalMs: 0, + heapObjectCacheHits: 0, + heapObjectCacheMisses: 0, + heapObjectCacheHitAwaitTotalMs: 0, + heapObjectCacheMissAwaitTotalMs: 0, + heapObjectGetTotalMs: 0, + heapObjectSerializeTotalMs: 0, + heapObjectInsertAwaitTotalMs: 0, + branchStats: new Map(), + heapObjectCacheMissesByShape: new Map(), + heapObjectCacheMissInlineNodeCountsByShape: new Map(), + }; +} + +function incrementMapCount(map: Map, key: string) { + map.set(key, (map.get(key) ?? 0) + 1); +} + +function addMapCount(map: Map, key: string, value: number) { + map.set(key, (map.get(key) ?? 0) + value); +} + +function emptyPiledriverInlineNodeCounts(): PiledriverInlineNodeCounts { + return { + primitiveNodes: 0, + arrayNodes: 0, + objectNodes: 0, + heapReferenceNodes: 0, + }; +} + +function addPiledriverInlineNodeCounts(target: PiledriverInlineNodeCounts, source: PiledriverInlineNodeCounts) { + target.primitiveNodes += source.primitiveNodes; + target.arrayNodes += source.arrayNodes; + target.objectNodes += source.objectNodes; + target.heapReferenceNodes += source.heapReferenceNodes; +} + +function totalInlineNodes(counts: PiledriverInlineNodeCounts) { + return counts.primitiveNodes + counts.arrayNodes + counts.objectNodes + counts.heapReferenceNodes; +} + +function countPiledriverInlineNodes(obj: PiledriverObject, path: Set = new Set()): PiledriverInlineNodeCounts { + switch (typeof obj) { + case "number": + case "string": + case "boolean": { + return { ...emptyPiledriverInlineNodeCounts(), primitiveNodes: 1 }; + } + case "object": { + if (obj === null) return { ...emptyPiledriverInlineNodeCounts(), primitiveNodes: 1 }; + if (isPiledriverHeapObjectSymbol in obj) return { ...emptyPiledriverInlineNodeCounts(), heapReferenceNodes: 1 }; + if (path.has(obj)) throw new Error("Piledriver objects must not contain cycles"); + const childPath = new Set(path).add(obj); + const counts = emptyPiledriverInlineNodeCounts(); + if (Array.isArray(obj)) { + counts.arrayNodes++; + for (const item of obj) addPiledriverInlineNodeCounts(counts, countPiledriverInlineNodes(item, childPath)); + } else { + counts.objectNodes++; + for (const value of Object.values(obj)) addPiledriverInlineNodeCounts(counts, countPiledriverInlineNodes(value, childPath)); + } + return counts; + } + default: { + throw new Error("Assertion error: Unknown type of Piledriver object " + typeof obj); + } + } +} + +function classifyHeapObjectPayload(obj: PiledriverObject): string { + if (obj === null) return "null"; + if (Array.isArray(obj)) return `array:${obj.length}`; + if (typeof obj !== "object") return typeof obj; + const keys = Object.keys(obj).sort(); + if (keys.includes("entries") && keys.includes("children") && keys.includes("augmentation") && keys.includes("size") && keys.includes("minKey") && keys.includes("maxKey")) { + const entries = Reflect.get(obj, "entries"); + const children = Reflect.get(obj, "children"); + return `btree-node:entries=${Array.isArray(entries) ? entries.length : "?"}:children=${Array.isArray(children) ? children.length : "?"}`; + } + if (keys.includes("key") && keys.includes("id") && keys.length === 2) return "multi-key"; + if (keys.includes("groupKey") && keys.includes("rows") && keys.length === 2) return "group-with-rows"; + if (keys.includes("inputRowData") && keys.includes("outputRowData") && keys.includes("stateAfter")) return "left-fold-row"; + if (keys.includes("state") && keys.includes("nextTriggerTimeMs") && keys.includes("emittedRows")) return "time-fold-row"; + if (keys.includes("outputRows") && keys.length === 1) return "time-fold-group"; + if (keys.includes("rowData") && keys.includes("rowIdentifier") && keys.includes("rowSortKey") && keys.includes("groupKey")) return "row-object"; + return `object:${keys.slice(0, 6).join(",")}${keys.length > 6 ? ",..." : ""}`; +} + +function serializationBranchKey(path: readonly string[]): string { + if (path[0] === "snapshot" && path[1] === "serializedTables") return `table:${path[2]}`; + return path[0] ?? ""; +} + +function serializationBranchStatsByKey(stats: PiledriverSerializationTimingStats | undefined, branchKey: string) { + if (stats === undefined) return undefined; + let result = stats.branchStats.get(branchKey); + if (result === undefined) { + result = emptyPiledriverSerializationBranchStats(); + stats.branchStats.set(branchKey, result); + } + return result; +} export function declarePiledriverDatabase(lowLevelDb: LowLevelDatabase, options: PiledriverDatabaseOptions = {}): PiledriverDatabase { // TODO actually support cycles both for heap and non-heap objects (right now they are detected and rejected) @@ -93,35 +258,79 @@ export function declarePiledriverDatabase(lowLevelDb: LowLevelDatabase, options: heapObjectsByHeapKeyFinalizer.register(heapObj, [keyBase64, refIdentity]); }; - const getHeapKeyAndSeq = async (heapObj: PiledriverHeapObject, path: SerializationPath = emptySerializationPath): Promise<{ key: ArrayBuffer, seq: DatabaseSeq }> => { + // Deduplicates and drops initial seqs before delegating to the low-level combineSeqs. This is + // important for performance: each low-level combined seq allocates promises/map entries, so we + // only want to create one when there are actually ≥2 distinct non-initial seqs to combine. + // (Identity comparison against initialSeq is safe because initialSeq is a singleton object.) + const combineSeqsDeduped = (seqs: Iterable): DatabaseSeq => { + const unique = [...new Set(seqs)].filter(seq => seq !== lowLevelDb.initialSeq); + if (unique.length === 0) return lowLevelDb.initialSeq; + if (unique.length === 1) return unique[0]; + return lowLevelDb.combineSeqs(...unique); + }; + + const getHeapKeyAndSeq = async (heapObj: PiledriverHeapObject, heapPath: HeapSerializationPath, serializationTimingStats: PiledriverSerializationTimingStats | undefined, branchKey: string | undefined): Promise<{ key: ArrayBuffer, seq: DatabaseSeq }> => { // Must be checked before the memo lookup: awaiting the memoized promise of an ancestor // that is still being serialized would deadlock. - if (path.heapObjects.has(heapObj)) throw new Error("Piledriver objects must not contain cycles (found a cycle of heap objects)"); + if (heapPath.has(heapObj)) throw new Error("Piledriver objects must not contain cycles (found a cycle of heap objects)"); const existing = heapKeysAndSeqByHeapObjects.get(heapObj); - if (existing) return await existing; + if (existing) { + if (serializationTimingStats !== undefined) { + serializationTimingStats.heapObjectCacheHits++; + const branch = branchKey === undefined ? undefined : serializationBranchStatsByKey(serializationTimingStats, branchKey); + if (branch !== undefined) branch.heapObjectCacheHits++; + } + const cacheHitAwaitStartedAt = performance.now(); + try { + return await existing; + } finally { + if (serializationTimingStats !== undefined) serializationTimingStats.heapObjectCacheHitAwaitTotalMs += performance.now() - cacheHitAwaitStartedAt; + } + } + if (serializationTimingStats !== undefined) { + serializationTimingStats.heapObjectCacheMisses++; + const branch = branchKey === undefined ? undefined : serializationBranchStatsByKey(serializationTimingStats, branchKey); + if (branch !== undefined) branch.heapObjectCacheMisses++; + } const promise = (async () => { - // A heap object starts a fresh plain-object path; plain object cycles can't span heap - // boundaries without also forming a heap cycle, which is tracked separately. - const childPath: SerializationPath = { objects: new Set(), heapObjects: new Set(path.heapObjects).add(heapObj) }; - return await traceSpan("bulldozer-js.piledriver.heap.serializeAndInsert", async () => { - const serialized = await serializePiledriverObject(await heapObj.get(), childPath); - const inserted = await heapDump.insertAll([serialized.buffer]); - return { - key: inserted.keys[0], - seq: lowLevelDb.combineSeqs(serialized.seq, inserted.seq), - }; + const childHeapPath = new Set(heapPath).add(heapObj); + return await traceSpanHot("bulldozer-js.piledriver.heap.serializeAndInsert", async () => { + const heapObjectGetStartedAt = performance.now(); + const heapObject = await heapObj.get(); + if (serializationTimingStats !== undefined) { + const shape = classifyHeapObjectPayload(heapObject); + const inlineNodeCount = totalInlineNodes(countPiledriverInlineNodes(heapObject)); + incrementMapCount(serializationTimingStats.heapObjectCacheMissesByShape, shape); + addMapCount(serializationTimingStats.heapObjectCacheMissInlineNodeCountsByShape, shape, inlineNodeCount); + const branch = branchKey === undefined ? undefined : serializationBranchStatsByKey(serializationTimingStats, branchKey); + if (branch !== undefined) { + incrementMapCount(branch.heapObjectCacheMissesByShape, shape); + addMapCount(branch.heapObjectCacheMissInlineNodeCountsByShape, shape, inlineNodeCount); + } + serializationTimingStats.heapObjectGetTotalMs += performance.now() - heapObjectGetStartedAt; + } + const heapObjectSerializeStartedAt = performance.now(); + const serialized = await serializePiledriverObject(heapObject, childHeapPath, serializationTimingStats, branchKey); + if (serializationTimingStats !== undefined) serializationTimingStats.heapObjectSerializeTotalMs += performance.now() - heapObjectSerializeStartedAt; + const heapObjectInsertStartedAt = performance.now(); + const inserted = await heapDump.insertAll([serialized.buffer], { requiresSeq: serialized.seq }); + if (serializationTimingStats !== undefined) serializationTimingStats.heapObjectInsertAwaitTotalMs += performance.now() - heapObjectInsertStartedAt; + return { key: inserted.keys[0], seq: inserted.seq }; }); })(); heapKeysAndSeqByHeapObjects.set(heapObj, promise); let result; + const cacheMissAwaitStartedAt = performance.now(); try { result = await promise; } catch (error) { // Don't leave a poisoned rejected promise in the cache; a later retry may succeed. if (heapKeysAndSeqByHeapObjects.get(heapObj) === promise) heapKeysAndSeqByHeapObjects.delete(heapObj); throw error; + } finally { + if (serializationTimingStats !== undefined) serializationTimingStats.heapObjectCacheMissAwaitTotalMs += performance.now() - cacheMissAwaitStartedAt; } cacheHeapObjectByKey(result.key, heapObj, result.seq); return result; @@ -145,7 +354,7 @@ export function declarePiledriverDatabase(lowLevelDb: LowLevelDatabase, options: let loadPromise: Promise | undefined; const heapObj: PiledriverHeapObject = { async get() { - loadPromise ??= traceSpan({ description: "bulldozer-js.piledriver.heap.get", attributes: { "bulldozer.piledriver.heap_read_cache_disabled": options.disableHeapReadCache === true } }, async () => { + loadPromise ??= traceSpanHot({ description: "bulldozer-js.piledriver.heap.get", attributes: { "bulldozer.piledriver.heap_read_cache_disabled": options.disableHeapReadCache === true } }, async () => { const { buffer, seq: heapSeq } = await heapDump.get(key); if (buffer === null) throw new Error(`Assertion error: Heap object with base64 key "${keyBase64}" not found`); const deserialized = await deserializePiledriverObject(buffer, heapSeq); @@ -167,104 +376,202 @@ export function declarePiledriverDatabase(lowLevelDb: LowLevelDatabase, options: return { object: heapObj, seq }; }; - const serializePiledriverObjectToJsonableObject = async (obj: PiledriverObject, path: SerializationPath): Promise<{ jsonableObject: unknown, seq: DatabaseSeq }> => { - switch (typeof obj) { - case "number": { - if (!Number.isFinite(obj)) return { jsonableObject: [obj.toString()], seq: lowLevelDb.initialSeq }; - if (Object.is(obj, -0)) return { jsonableObject: ["-0"], seq: lowLevelDb.initialSeq }; - // intentionally fall through to the primitive case below - } - case "string": - case "boolean": { - return { jsonableObject: obj, seq: lowLevelDb.initialSeq }; - } - case "object": { - if (obj === null) { - return { jsonableObject: obj, seq: lowLevelDb.initialSeq }; - } else if (Array.isArray(obj)) { - if (path.objects.has(obj)) throw new Error("Piledriver objects must not contain cycles"); - const childPath: SerializationPath = { ...path, objects: new Set(path.objects).add(obj) }; - const itemsSerializeResults = await Promise.all(obj.map(async o => await serializePiledriverObjectToJsonableObject(o, childPath))); - return { - jsonableObject: ["array", itemsSerializeResults.map(r => r.jsonableObject)], - seq: lowLevelDb.combineSeqs(...itemsSerializeResults.map(r => r.seq)), - }; - } else if (isPiledriverHeapObjectSymbol in obj) { - const heapKeyAndSeq = await getHeapKeyAndSeq(obj, path); - return { - jsonableObject: ["heap-reference", encodeBase64(new Uint8Array(heapKeyAndSeq.key))], - seq: heapKeyAndSeq.seq, - }; - } else { - // "normal" object - // TODO: assert this is a POJO + // A heap reference discovered during the synchronous payload walk. The jsonable slot is + // created immediately (as ["heap-reference", null]) and patched with the base64 key once the + // referenced heap object has been resolved/inserted. + type PendingHeapReferenceSlot = { + slot: [string, string | null], + heapObj: PiledriverHeapObject, + branchKey: string | undefined, + }; - if (path.objects.has(obj)) throw new Error("Piledriver objects must not contain cycles"); - const childPath: SerializationPath = { ...path, objects: new Set(path.objects).add(obj) }; - const entriesSerializeResults = await Promise.all(Object.entries(obj).map(async ([k, v]) => [k, await serializePiledriverObjectToJsonableObject(v, childPath)] as const)); - return { - jsonableObject: Object.fromEntries(entriesSerializeResults.map(([k, v]) => [k, v.jsonableObject] as const)), - seq: lowLevelDb.combineSeqs(...entriesSerializeResults.map(([_, v]) => v.seq)), - }; + // Serializes a Piledriver object in two phases: + // 1. A fully SYNCHRONOUS walk that builds the jsonable structure, detects plain-object + // cycles (push/pop set — safe because nothing interleaves during a sync walk), counts + // stats, and records one slot per heap reference. + // 2. Resolution of the (deduplicated) referenced heap objects in parallel, then patching + // their base64 keys into the recorded slots. + // This replaces a previous fully-async recursive serializer that allocated promises for every + // node and called lowLevelDb.combineSeqs once per array/object node (each combined seq + // allocates a UUID, tracking promises, and map entries). Profiling showed that overhead — not + // LMDB — dominated CPU during backfills, so seqs are now combined exactly once per heap + // object/root, and only heap references involve async work at all. + const serializePiledriverObject = async (obj: PiledriverObject, heapPath: HeapSerializationPath, serializationTimingStats: PiledriverSerializationTimingStats | undefined, inheritedBranchKey?: string): Promise<{ buffer: ArrayBuffer, seq: DatabaseSeq }> => { + const stats = serializationTimingStats; + const pendingSlots: PendingHeapReferenceSlot[] = []; + const objectPath = new Set(); + // Branch keys only depend on the first 3 path segments (see serializationBranchKey), so we + // stop tracking the key path once the branch is determined. Nested heap objects inherit the + // branch key of their reference site, which is equivalent to the old logicalPath threading + // because heap references only occur at depth >= 3 in the root snapshot. + const keyPath: string[] = []; + + const build = (node: PiledriverObject, branch: PiledriverSerializationBranchStats | undefined, branchKey: string | undefined, branchDetermined: boolean): unknown => { + switch (typeof node) { + case "number": { + if (stats !== undefined) { + stats.primitiveNodes++; + if (branch !== undefined) branch.primitiveNodes++; + } + if (!Number.isFinite(node)) return [node.toString()]; + if (Object.is(node, -0)) return ["-0"]; + return node; + } + case "string": + case "boolean": { + if (stats !== undefined) { + stats.primitiveNodes++; + if (branch !== undefined) branch.primitiveNodes++; + } + return node; + } + case "object": { + if (node === null) { + if (stats !== undefined) { + stats.primitiveNodes++; + if (branch !== undefined) branch.primitiveNodes++; + } + return node; + } else if (Array.isArray(node)) { + if (stats !== undefined) { + stats.arrayNodes++; + stats.arrayItems += node.length; + if (branch !== undefined) branch.arrayNodes++; + } + if (objectPath.has(node)) throw new Error("Piledriver objects must not contain cycles"); + objectPath.add(node); + const items = node.map(item => build(item, branch, branchKey, branchDetermined)); + objectPath.delete(node); + return ["array", items]; + } else if (isPiledriverHeapObjectSymbol in node) { + if (stats !== undefined) { + stats.heapReferenceNodes++; + if (branch !== undefined) branch.heapReferenceNodes++; + } + // Fail fast on heap cycles at walk time (resolution would deadlock on the ancestor's + // own memoized promise otherwise). + if (heapPath.has(node)) throw new Error("Piledriver objects must not contain cycles (found a cycle of heap objects)"); + const slot: [string, string | null] = ["heap-reference", null]; + pendingSlots.push({ slot, heapObj: node, branchKey }); + return slot; + } else { + // "normal" object + // TODO: assert this is a POJO + + if (objectPath.has(node)) throw new Error("Piledriver objects must not contain cycles"); + objectPath.add(node); + const entries = Object.entries(node); + if (stats !== undefined) { + stats.objectNodes++; + stats.objectEntries += entries.length; + if (branch !== undefined) { + branch.objectNodes++; + branch.objectEntries += entries.length; + } + } + const result: Record = {}; + for (const [k, v] of entries) { + let childBranch = branch; + let childBranchKey = branchKey; + let childBranchDetermined = branchDetermined; + if (!branchDetermined) { + keyPath.push(k); + childBranchKey = serializationBranchKey(keyPath); + childBranch = stats === undefined ? undefined : serializationBranchStatsByKey(stats, childBranchKey); + childBranchDetermined = keyPath.length >= 3; + } + result[k] = build(v, childBranch, childBranchKey, childBranchDetermined); + if (!branchDetermined) keyPath.pop(); + } + objectPath.delete(node); + return result; + } + } + default: { + throw new Error("Assertion error: Unknown type of Piledriver object " + typeof node); } } - default: { - throw new Error("Assertion error: Unknown type of Piledriver object " + typeof obj); - } - } - }; - - const serializePiledriverObject = async (obj: PiledriverObject, path: SerializationPath = emptySerializationPath): Promise<{ buffer: ArrayBuffer, seq: DatabaseSeq }> => { - const toJsonableResponse = await serializePiledriverObjectToJsonableObject(obj, path); - return { - buffer: new TextEncoder().encode(JSON.stringify(toJsonableResponse.jsonableObject)).buffer, - seq: toJsonableResponse.seq, }; + + const toJsonableStartedAt = performance.now(); + const inheritedBranch = inheritedBranchKey === undefined ? undefined : serializationBranchStatsByKey(stats, inheritedBranchKey); + const jsonableObject = build(obj, inheritedBranch, inheritedBranchKey, inheritedBranchKey !== undefined); + if (stats !== undefined) stats.serializeToJsonableTotalMs += performance.now() - toJsonableStartedAt; + + let seq = lowLevelDb.initialSeq; + if (pendingSlots.length > 0) { + // Resolve each distinct heap object once, even if it is referenced from multiple slots. + const slotsByHeapObj = new Map(); + for (const pendingSlot of pendingSlots) { + const existing = slotsByHeapObj.get(pendingSlot.heapObj); + if (existing === undefined) slotsByHeapObj.set(pendingSlot.heapObj, [pendingSlot]); + else existing.push(pendingSlot); + } + const resolvedSeqs = await Promise.all([...slotsByHeapObj.entries()].map(async ([heapObj, slots]) => { + const heapKeyAndSeq = await getHeapKeyAndSeq(heapObj, heapPath, stats, slots[0].branchKey); + const keyBase64 = encodeBase64(new Uint8Array(heapKeyAndSeq.key)); + for (const { slot } of slots) slot[1] = keyBase64; + return heapKeyAndSeq.seq; + })); + seq = combineSeqsDeduped(resolvedSeqs); + } + + const jsonStringifyStartedAt = performance.now(); + const json = JSON.stringify(jsonableObject); + if (stats !== undefined) stats.jsonStringifyTotalMs += performance.now() - jsonStringifyStartedAt; + const textEncodeStartedAt = performance.now(); + const buffer = textEncoder.encode(json).buffer; + if (stats !== undefined) stats.textEncodeTotalMs += performance.now() - textEncodeStartedAt; + return { buffer, seq }; }; - const deserializePiledriverObjectFromJsonableObject = async (jsonableObject: unknown, enclosingSeq: DatabaseSeq): Promise<{ object: PiledriverObject, seq: DatabaseSeq }> => { + // Fully synchronous (getHeapObjectByKey is sync; heap payloads are only fetched lazily on + // .get()). Seqs are collected into one array and combined once per buffer instead of once per + // node — see serializePiledriverObject for why this matters. + const deserializePiledriverObjectFromJsonableObject = (jsonableObject: unknown, enclosingSeq: DatabaseSeq, seqs: DatabaseSeq[]): PiledriverObject => { switch (typeof jsonableObject) { case "string": case "number": case "boolean": { - return { object: jsonableObject, seq: lowLevelDb.initialSeq }; + return jsonableObject; } case "object": { if (jsonableObject === null) { - return { object: jsonableObject, seq: lowLevelDb.initialSeq }; + return jsonableObject; } else if (Array.isArray(jsonableObject)) { switch (jsonableObject[0]) { case "array": { - const itemsDeserializeResults = await Promise.all(jsonableObject[1].map(async (o: any) => await deserializePiledriverObjectFromJsonableObject(o, enclosingSeq))); - return { object: itemsDeserializeResults.map(r => r.object), seq: lowLevelDb.combineSeqs(...itemsDeserializeResults.map(r => r.seq)) }; + // any: JSON.parse output is structurally validated by the surrounding switch; a malformed + // payload would throw in the recursive call rather than silently passing through. + return jsonableObject[1].map((o: any) => deserializePiledriverObjectFromJsonableObject(o, enclosingSeq, seqs)); } case "heap-reference": { const heapObjAndSeq = getHeapObjectByKey(decodeBase64(jsonableObject[1]).buffer, enclosingSeq); - return { object: heapObjAndSeq.object, seq: heapObjAndSeq.seq }; + seqs.push(heapObjAndSeq.seq); + return heapObjAndSeq.object; } case "NaN": { - return { object: NaN, seq: lowLevelDb.initialSeq }; + return NaN; } case "Infinity": { - return { object: Infinity, seq: lowLevelDb.initialSeq }; + return Infinity; } case "-Infinity": { - return { object: -Infinity, seq: lowLevelDb.initialSeq }; + return -Infinity; } case "-0": { - return { object: -0, seq: lowLevelDb.initialSeq }; + return -0; } default: { throw new Error("Assertion error: Serialized Piledriver JSONable object array has unknown type " + jsonableObject[0]); } } } else { - const entries = Object.entries(jsonableObject); - const entriesDeserializeResults = await Promise.all(entries.map(async ([k, v]) => [k, await deserializePiledriverObjectFromJsonableObject(v, enclosingSeq)] as const)); - return { - object: Object.fromEntries(entriesDeserializeResults.map(([k, v]) => [k, v.object] as const)), - seq: lowLevelDb.combineSeqs(...entriesDeserializeResults.map(([_, v]) => v.seq)), - }; + const result: Record = {}; + for (const [k, v] of Object.entries(jsonableObject)) { + result[k] = deserializePiledriverObjectFromJsonableObject(v, enclosingSeq, seqs); + } + return result; } } default: { @@ -274,7 +581,9 @@ export function declarePiledriverDatabase(lowLevelDb: LowLevelDatabase, options: }; const deserializePiledriverObject = async (buffer: ArrayBuffer, enclosingSeq: DatabaseSeq): Promise<{ object: PiledriverObject, seq: DatabaseSeq }> => { - return await deserializePiledriverObjectFromJsonableObject(JSON.parse(new TextDecoder().decode(buffer)), enclosingSeq); + const seqs: DatabaseSeq[] = []; + const object = deserializePiledriverObjectFromJsonableObject(JSON.parse(textDecoder.decode(buffer)), enclosingSeq, seqs); + return { object, seq: combineSeqsDeduped(seqs) }; }; const parseDebugEntryValue = (valueUtf8: string | null) => { @@ -287,6 +596,20 @@ export function declarePiledriverDatabase(lowLevelDb: LowLevelDatabase, options: }; return { + getDebugInfo() { + return { + backend: "piledriver", + constructorArguments: { lowLevelDb, options }, + lowLevelDb, + rootStore, + heapDump, + heapObjectsByObject, + heapObjectsByHeapKeyBase64, + heapObjectsByHeapKeyFinalizer, + heapKeysAndSeqByHeapObjects, + heapReadCacheDisabled: options.disableHeapReadCache === true, + }; + }, async getRootObject(key): Promise<{ object: PiledriverObject, seq: DatabaseSeq }> { return await traceSpan("bulldozer-js.piledriver.getRootObject", async () => { const { buffer, seq: rootSeq } = await rootStore.get(key); @@ -297,8 +620,71 @@ export function declarePiledriverDatabase(lowLevelDb: LowLevelDatabase, options: }, async setRootObject(key, value): Promise<{ seq: DatabaseSeq }> { return await traceSpan("bulldozer-js.piledriver.setRootObject", async () => { - const { buffer, seq } = await serializePiledriverObject(value); + const timingStats = emptyPiledriverSerializationTimingStats(); + const startedAt = performance.now(); + const serializeStartedAt = performance.now(); + const serializeCpuStartedAt = process.cpuUsage(); + const { buffer, seq } = await serializePiledriverObject(value, new Set(), timingStats); + const serializeCpuUsage = process.cpuUsage(serializeCpuStartedAt); + const serializePiledriverObjectMs = performance.now() - serializeStartedAt; + const serializeCpuMs = (serializeCpuUsage.user + serializeCpuUsage.system) / 1000; + const rootStoreSetAllStartedAt = performance.now(); const { seq: rootSeq } = await rootStore.setAll([{ key, value: buffer }], { requiresSeq: seq }); + const rootStoreSetAllMs = performance.now() - rootStoreSetAllStartedAt; + const topSerializationBranches = [...timingStats.branchStats.entries()] + .map(([branch, stats]) => ({ + branch, + totalNodes: stats.primitiveNodes + stats.arrayNodes + stats.objectNodes + stats.heapReferenceNodes, + primitiveNodes: stats.primitiveNodes, + arrayNodes: stats.arrayNodes, + objectNodes: stats.objectNodes, + objectEntries: stats.objectEntries, + heapReferenceNodes: stats.heapReferenceNodes, + heapObjectCacheHits: stats.heapObjectCacheHits, + heapObjectCacheMisses: stats.heapObjectCacheMisses, + topHeapObjectCacheMissShapes: [...stats.heapObjectCacheMissesByShape.entries()] + .map(([shape, count]) => { + const totalInlineNodeCount = stats.heapObjectCacheMissInlineNodeCountsByShape.get(shape) ?? 0; + return { shape, count, totalInlineNodeCount, averageInlineNodeCount: count === 0 ? 0 : totalInlineNodeCount / count }; + }) + .sort((a, b) => b.count - a.count) + .slice(0, 5), + })) + .sort((a, b) => b.totalNodes - a.totalNodes) + .slice(0, 5); + const topHeapObjectCacheMissShapes = [...timingStats.heapObjectCacheMissesByShape.entries()] + .map(([shape, count]) => { + const totalInlineNodeCount = timingStats.heapObjectCacheMissInlineNodeCountsByShape.get(shape) ?? 0; + return { shape, count, totalInlineNodeCount, averageInlineNodeCount: count === 0 ? 0 : totalInlineNodeCount / count }; + }) + .sort((a, b) => b.count - a.count) + .slice(0, 10); + console.debug("bulldozer-js piledriver setRootObject timing", { + elapsedMs: performance.now() - startedAt, + serializePiledriverObjectMs, + serializeCpuMs, + serializeCpuToWallRatio: serializePiledriverObjectMs === 0 ? 0 : serializeCpuMs / serializePiledriverObjectMs, + rootStoreSetAllMs, + rootValueBytes: buffer.byteLength, + primitiveNodes: timingStats.primitiveNodes, + arrayNodes: timingStats.arrayNodes, + arrayItems: timingStats.arrayItems, + objectNodes: timingStats.objectNodes, + objectEntries: timingStats.objectEntries, + heapReferenceNodes: timingStats.heapReferenceNodes, + serializeToJsonableTotalMs: timingStats.serializeToJsonableTotalMs, + jsonStringifyTotalMs: timingStats.jsonStringifyTotalMs, + textEncodeTotalMs: timingStats.textEncodeTotalMs, + heapObjectCacheHits: timingStats.heapObjectCacheHits, + heapObjectCacheMisses: timingStats.heapObjectCacheMisses, + heapObjectCacheHitAwaitTotalMs: timingStats.heapObjectCacheHitAwaitTotalMs, + heapObjectCacheMissAwaitTotalMs: timingStats.heapObjectCacheMissAwaitTotalMs, + heapObjectGetTotalMs: timingStats.heapObjectGetTotalMs, + heapObjectSerializeTotalMs: timingStats.heapObjectSerializeTotalMs, + heapObjectInsertAwaitTotalMs: timingStats.heapObjectInsertAwaitTotalMs, + topHeapObjectCacheMissShapes, + topSerializationBranches, + }); return { seq: rootSeq }; }); }, diff --git a/apps/bulldozer-js/src/index.ts b/apps/bulldozer-js/src/index.ts index b3fe26cfb..9d8415050 100644 --- a/apps/bulldozer-js/src/index.ts +++ b/apps/bulldozer-js/src/index.ts @@ -10,13 +10,13 @@ import { mkdirSync, mkdtempSync } from "node:fs"; import { tmpdir } from "node:os"; import { join } from "node:path"; import { getHeapStatistics } from "node:v8"; +import { isBulldozerRequestAuthorized } from "./auth.js"; import { declareBulldozerDatabase, type BulldozerDatabase } from "./databases/bulldozer/index.js"; import { declareInMemoryLowLevelDatabase } from "./databases/low-level/implementations/in-memory.js"; import { declareInstantAvailabilityLowLevelDatabase } from "./databases/low-level/implementations/instant-availability.js"; import { declareLmdbLowLevelDatabase } from "./databases/low-level/implementations/lmdb.js"; import type { LowLevelDatabase } from "./databases/low-level/index.js"; import { declarePiledriverDatabase, type PiledriverObject } from "./databases/piledriver/index.js"; -import { isBulldozerRequestAuthorized } from "./auth.js"; import "./load-env.js"; import { instrumentation, traceSpan } from "./otel.js"; import { createPaymentsSchema, itemQuantitiesLedgerUpperBoundAsOf } from "./payments/schema/index.js"; @@ -30,6 +30,7 @@ const USD_CURRENCY = SUPPORTED_CURRENCIES.find(currency => currency.code === "US const schema = createPaymentsSchema(); const port = Number(process.env.BULLDOZER_JS_PORT ?? process.env.BULLDOZER_SERVER_PORT ?? `${process.env.NEXT_PUBLIC_HEXCLAVE_PORT_PREFIX ?? "81"}46`); const HEAP_GC_USAGE_THRESHOLD = 0.6; +const HEAP_GC_TARGET_USAGE_THRESHOLD = 0.3; const HEAP_GC_MAX_PASSES = 5; const HEAP_GC_FINALIZATION_DELAY_MS = 20; const HEAP_GC_RETRY_COOLDOWN_MS = 60_000; @@ -75,6 +76,8 @@ const bulldozerDb = declareBulldozerDatabase( }), { migrations: schema.migrations }, ); +(globalThis as any).bulldozerDb = bulldozerDb; +console.log(`Stored bulldozerDb in globalThis for pid ${process.pid}. Run \`kill -USR1 ${process.pid} && node inspect 127.0.0.1:9229\` and then \`exec("globalThis.bulldozerDb")\` to inspect it.`); await traceSpan("bulldozer-js.applyRemainingMigrations", async () => await bulldozerDb.applyRemainingMigrations()); function jsonResponse(body: unknown, init?: ResponseInit) { @@ -147,6 +150,7 @@ function delayNextHeapGcMaintenance(reason: string, label: string, usage: Return label, reason, threshold: HEAP_GC_USAGE_THRESHOLD, + targetThreshold: HEAP_GC_TARGET_USAGE_THRESHOLD, retryAfterMs: HEAP_GC_RETRY_COOLDOWN_MS, usage, }); @@ -191,7 +195,7 @@ async function runHeapGcMaintenanceIfNeeded(label: string) { } const startedAt = performance.now(); - logHeapGcMaintenance("heap-gc-start", { label, threshold: HEAP_GC_USAGE_THRESHOLD, before }); + logHeapGcMaintenance("heap-gc-start", { label, threshold: HEAP_GC_USAGE_THRESHOLD, targetThreshold: HEAP_GC_TARGET_USAGE_THRESHOLD, before }); let previous = before; let completedPasses = 0; @@ -204,10 +208,11 @@ async function runHeapGcMaintenanceIfNeeded(label: string) { const afterPass = currentHeapUsage(); const passElapsedMs = performance.now() - passStartedAt; - const thresholdReached = afterPass.heapUsedRatio <= HEAP_GC_USAGE_THRESHOLD; + const targetThresholdReached = afterPass.heapUsedRatio <= HEAP_GC_TARGET_USAGE_THRESHOLD; logHeapGcMaintenance("heap-gc-pass", { label, pass, + targetThreshold: HEAP_GC_TARGET_USAGE_THRESHOLD, before: previous, after: afterPass, freedHeapMb: (previous.heapUsed - afterPass.heapUsed) / 1_000_000, @@ -217,13 +222,14 @@ async function runHeapGcMaintenanceIfNeeded(label: string) { }); previous = afterPass; completedPasses = pass; - if (thresholdReached) break; + if (targetThresholdReached) break; } const after = currentHeapUsage(); logHeapGcMaintenance("heap-gc-finish", { label, threshold: HEAP_GC_USAGE_THRESHOLD, + targetThreshold: HEAP_GC_TARGET_USAGE_THRESHOLD, after, totalFreedHeapMb: (before.heapUsed - after.heapUsed) / 1_000_000, completedPasses, @@ -231,12 +237,12 @@ async function runHeapGcMaintenanceIfNeeded(label: string) { elapsedMs: performance.now() - startedAt, }); - if (after.heapUsedRatio > HEAP_GC_USAGE_THRESHOLD) { + if (after.heapUsedRatio > HEAP_GC_TARGET_USAGE_THRESHOLD) { captureError("bulldozer-js:heap-still-above-threshold-after-gc", new HexclaveAssertionError( - "Bulldozer JS heap remained above the GC threshold after explicit collection", - { label, threshold: HEAP_GC_USAGE_THRESHOLD, before, after }, + "Bulldozer JS heap remained above the GC target threshold after explicit collection", + { label, threshold: HEAP_GC_USAGE_THRESHOLD, targetThreshold: HEAP_GC_TARGET_USAGE_THRESHOLD, before, after }, )); - delayNextHeapGcMaintenance("still-above-threshold", label, after); + delayNextHeapGcMaintenance("still-above-target-threshold", label, after); } else { heapGcMaintenanceRetryAfter = 0; } diff --git a/apps/bulldozer-js/src/otel.ts b/apps/bulldozer-js/src/otel.ts index 4a983dc4e..35d8a8e72 100644 --- a/apps/bulldozer-js/src/otel.ts +++ b/apps/bulldozer-js/src/otel.ts @@ -28,3 +28,18 @@ export async function traceSpan(optionsOrDescription: string | { description: return await fn(span); }); } + +const hotPathTracingEnabled = getEnvVariable("HEXCLAVE_BULLDOZER_HOT_PATH_TRACING", "") === "true"; +const noopTraceSpan: TraceSpan = { setAttribute: () => {} }; + +/** + * Like traceSpan, but for operations that run at very high frequency (per KV put, per seq, per + * heap object, ...). CPU profiling showed span creation alone was >20% of process CPU during + * backfills (plus a large share of GC), so these spans are disabled unless + * HEXCLAVE_BULLDOZER_HOT_PATH_TRACING=true is set. Coarse operations (setRootObject, snapshot + * mutations, HTTP handlers) keep using traceSpan unconditionally. + */ +export async function traceSpanHot(optionsOrDescription: string | { description: string, attributes?: Record }, fn: (span: TraceSpan) => Promise): Promise { + if (!hotPathTracingEnabled) return await fn(noopTraceSpan); + return await traceSpan(optionsOrDescription, fn); +} diff --git a/apps/bulldozer-js/src/payments/schema/index.test.ts b/apps/bulldozer-js/src/payments/schema/index.test.ts index 788fea0a5..e8d0d4efd 100644 --- a/apps/bulldozer-js/src/payments/schema/index.test.ts +++ b/apps/bulldozer-js/src/payments/schema/index.test.ts @@ -209,7 +209,7 @@ describe("payments schema", () => { // With calendar-anchored repeats, the first monthly boundary off the epoch anchor is // 1970-02-01 (31 days), not the 30-day MONTH_MS approximation. const firstRepeatMillis = Date.UTC(1970, 1, 1); - snapshot = await snapshot.tick(new Date(firstRepeatMillis)); + snapshot = (await snapshot.tick(new Date(firstRepeatMillis))).newSnapshot; expect(await balanceAt(snapshot, group, "credits", 0)).toBe(10); expect(await balanceAt(snapshot, group, "credits", firstRepeatMillis)).toBe(10); @@ -232,8 +232,8 @@ describe("payments schema", () => { endedAtMillis: subEndMillis, }) as unknown as PiledriverObject); - snapshot = await snapshot.tick(new Date(firstRepeatMillis)); - snapshot = await snapshot.tick(new Date(subEndMillis)); + snapshot = (await snapshot.tick(new Date(firstRepeatMillis))).newSnapshot; + snapshot = (await snapshot.tick(new Date(subEndMillis))).newSnapshot; const group = customerGroup("u-repeat"); const txns = ((await rowDatas(snapshot, schema.transactions, group)) as unknown as TransactionRow[]) @@ -270,7 +270,7 @@ describe("payments schema", () => { ...overrides, }) as unknown as PiledriverObject; snapshot = await set(snapshot, schema.subscriptions, "sub-rewrite", subRow()); - snapshot = await snapshot.tick(new Date(firstRepeatMillis)); + snapshot = (await snapshot.tick(new Date(firstRepeatMillis))).newSnapshot; const group = customerGroup("u-rewrite"); const txnIds = async () => ((await rowDatas(snapshot, schema.transactions, group)) as unknown as TransactionRow[]).map(txn => txn.txnId).sort(stringCompare); @@ -287,7 +287,7 @@ describe("payments schema", () => { // Quantity upgrade: history keeps the originally granted quantities; only future repeats scale. snapshot = await set(snapshot, schema.subscriptions, "sub-rewrite", subRow({ quantity: 2, currentPeriodStartMillis: firstRepeatMillis })); expect(await balanceAt(snapshot, group, "credits", firstRepeatMillis)).toBe(20); - snapshot = await snapshot.tick(new Date(secondRepeatMillis)); + snapshot = (await snapshot.tick(new Date(secondRepeatMillis))).newSnapshot; expect(await balanceAt(snapshot, group, "credits", secondRepeatMillis)).toBe(40); const secondGrant = ((await rowDatas(snapshot, schema.transactions, group)) as unknown as TransactionRow[]).find(txn => txn.txnId === `igr:sub-rewrite:${secondRepeatMillis}`); expect(secondGrant?.entries).toMatchObject([{ type: "item-quantity-change", itemId: "credits", quantity: 20 }]); @@ -314,7 +314,7 @@ describe("payments schema", () => { ...overrides, }); snapshot = await set(snapshot, schema.oneTimePurchases, "otp-rewrite", otpRow()); - snapshot = await snapshot.tick(new Date(firstRepeatMillis)); + snapshot = (await snapshot.tick(new Date(firstRepeatMillis))).newSnapshot; const group = customerGroup("u-otp-rewrite"); expect(await balanceAt(snapshot, group, "credits", firstRepeatMillis)).toBe(10); @@ -323,7 +323,7 @@ describe("payments schema", () => { // survive the write, and future repeats stop at the revocation. snapshot = await set(snapshot, schema.oneTimePurchases, "otp-rewrite", otpRow({ revokedAtMillis: Date.UTC(1970, 1, 10) })); expect(await balanceAt(snapshot, group, "credits", firstRepeatMillis)).toBe(10); - snapshot = await snapshot.tick(new Date(Date.UTC(1970, 2, 1))); + snapshot = (await snapshot.tick(new Date(Date.UTC(1970, 2, 1)))).newSnapshot; const txnIds = ((await rowDatas(snapshot, schema.transactions, group)) as unknown as TransactionRow[]).map(txn => txn.txnId).sort(stringCompare); expect(txnIds).toEqual([`igr:otp-rewrite:${firstRepeatMillis}`, "otp:otp-rewrite"]); }); @@ -341,12 +341,12 @@ describe("payments schema", () => { ...overrides, }) as unknown as PiledriverObject; snapshot = await set(snapshot, schema.subscriptions, "sub-seal", subRow()); - snapshot = await snapshot.tick(new Date(firstRepeatMillis)); + snapshot = (await snapshot.tick(new Date(firstRepeatMillis))).newSnapshot; // Cancellation arrives as a rewrite of the live row (that's how the Stripe sync works); the // end event must fire off the *existing* fold state, expiring the actually-emitted grants. snapshot = await set(snapshot, schema.subscriptions, "sub-seal", subRow({ status: "canceled", endedAtMillis: subEndMillis, canceledAtMillis: subEndMillis })); - snapshot = await snapshot.tick(new Date(subEndMillis)); + snapshot = (await snapshot.tick(new Date(subEndMillis))).newSnapshot; const group = customerGroup("u-seal"); const txns = ((await rowDatas(snapshot, schema.transactions, group)) as unknown as TransactionRow[]) @@ -362,7 +362,7 @@ describe("payments schema", () => { // Once ended, further webhook rewrites must not re-arm the fold: no duplicate subscription-end, // no resumed repeats past the end. snapshot = await set(snapshot, schema.subscriptions, "sub-seal", subRow({ status: "canceled", endedAtMillis: subEndMillis, canceledAtMillis: subEndMillis, currentPeriodStartMillis: firstRepeatMillis })); - snapshot = await snapshot.tick(new Date(Date.UTC(1970, 3, 1))); + snapshot = (await snapshot.tick(new Date(Date.UTC(1970, 3, 1)))).newSnapshot; const txnIdsAfter = ((await rowDatas(snapshot, schema.transactions, group)) as unknown as TransactionRow[]).map(txn => txn.txnId).sort(stringCompare); expect(txnIdsAfter).toEqual([`igr:sub-seal:${firstRepeatMillis}`, "sub-end:sub-seal", "sub-start:sub-seal"]); }); @@ -399,7 +399,7 @@ describe("payments schema", () => { // The fold is sealed: later rewrites and ticks add nothing (no duplicate end). snapshot = await set(snapshot, schema.subscriptions, "sub-switch", subRow({ status: "canceled", endedAtMillis: subEndMillis, canceledAtMillis: subEndMillis, currentPeriodStartMillis: subEndMillis })); - snapshot = await snapshot.tick(new Date(Date.UTC(1970, 2, 1))); + snapshot = (await snapshot.tick(new Date(Date.UTC(1970, 2, 1)))).newSnapshot; const txnIdsAfter = ((await rowDatas(snapshot, schema.transactions, group)) as unknown as TransactionRow[]).map(txn => txn.txnId).sort(stringCompare); expect(txnIdsAfter).toEqual(["sub-end:sub-switch", "sub-start:sub-switch"]); }); @@ -661,7 +661,7 @@ describe("transactions-by-tenancy date index", () => { product: product({ credits: { quantity: 10, repeat: [1, "month"], expires: "when-repeated" } }), currentPeriodEndMillis: 2 * MONTH_MS, }) as unknown as PiledriverObject); - snapshot = await snapshot.tick(new Date(firstRepeatMillis)); + snapshot = (await snapshot.tick(new Date(firstRepeatMillis))).newSnapshot; snapshot = await setRefund(snapshot, { txnId: "refund:sub-start:sub-grant:uuid1", customerId: "u-grant", createdAtMillis: 5_000 }); const txnIds = ((await rowDatas(snapshot, schema.transactions, customerGroup("u-grant"))) as unknown as TransactionRow[]) diff --git a/apps/bulldozer-js/src/payments/schema/index.ts b/apps/bulldozer-js/src/payments/schema/index.ts index 8b99c6313..87231cac0 100644 --- a/apps/bulldozer-js/src/payments/schema/index.ts +++ b/apps/bulldozer-js/src/payments/schema/index.ts @@ -668,7 +668,7 @@ export function createPaymentsSchema() { const subscription = rowObject(row.rowData); return { tenancyId: subscription.tenancyId, stripeSubscriptionId: subscription.stripeSubscriptionId }; }, - joinKeyComparator: compareJson, + joinKeyComparator: (a: any, b: any) => stringCompare(a.tenancyId, b.tenancyId) || stringCompare(a.stripeSubscriptionId ?? "", b.stripeSubscriptionId ?? "") || (a.stripeSubscriptionId === b.stripeSubscriptionId ? 0 : a.stripeSubscriptionId === null ? -1 : 1), joiner: async (left, right) => ({ leftRowData: left.rowData, rightRowData: right?.rowData ?? null }), }), { left: "payments-subscription-invoices", right: "payments-subscriptions" }), table("payments-renewal-invoice-rows", defineFilterTable(row => { diff --git a/apps/bulldozer-js/src/payments/schema/item-quantities.test.ts b/apps/bulldozer-js/src/payments/schema/item-quantities.test.ts index 7da1ae2fe..d6d761794 100644 --- a/apps/bulldozer-js/src/payments/schema/item-quantities.test.ts +++ b/apps/bulldozer-js/src/payments/schema/item-quantities.test.ts @@ -630,7 +630,7 @@ describe("item quantities: full-pipeline integration", () => { currentPeriodEndMillis: 11 * DAY_MS + MONTH_MS, createdAtMillis: 11 * DAY_MS, }) as unknown as PiledriverObject); - snapshot = await snapshot.tick(new Date(11 * DAY_MS)); + snapshot = (await snapshot.tick(new Date(11 * DAY_MS))).newSnapshot; expect(await balanceAt(snapshot, customerGroup("u-upgrade"), "emails", 11 * DAY_MS)).toBe(500); }); @@ -663,7 +663,7 @@ describe("item quantities: full-pipeline integration", () => { // The first monthly reset off the epoch anchor is 1970-02-01 (calendar-anchored, not 30 days), // still well before the manual grant's 3-month absolute expiry, so the reset ranks soonest. const firstResetMillis = Date.UTC(1970, 1, 1); - snapshot = await snapshot.tick(new Date(firstResetMillis)); + snapshot = (await snapshot.tick(new Date(firstResetMillis))).newSnapshot; expect(await balanceAt(snapshot, g, "emails", firstResetMillis)).toBe(200); }); }); diff --git a/apps/bulldozer-js/src/payments/schema/schema-test-helpers.ts b/apps/bulldozer-js/src/payments/schema/schema-test-helpers.ts index 3292d1d5c..db6b55e67 100644 --- a/apps/bulldozer-js/src/payments/schema/schema-test-helpers.ts +++ b/apps/bulldozer-js/src/payments/schema/schema-test-helpers.ts @@ -42,7 +42,7 @@ export const rowsBySortKey = async (snapshot: Snapshot, tableId: string, groupKe await collect(snapshot.listRowsInGroup({ tableId, groupKey, range: {} })); export const set = async (snapshot: Snapshot, tableId: string, rowIdentifier: string, newRowData: PiledriverObject | undefined) => - await snapshot.setOrDeleteRow({ tableId, rowIdentifier, newRowData }); + (await snapshot.setOrDeleteRow({ tableId, rowIdentifier, newRowData })).newSnapshot; export const customerGroup = (customerId: string, customerType: CustomerType = "user"): PiledriverObject => ({ tenancyId: "t1", customerType, customerId }); diff --git a/apps/dashboard/src/app/(main)/(protected)/(outside-dashboard)/new-project/page-client-parts/project-onboarding-wizard.tsx b/apps/dashboard/src/app/(main)/(protected)/(outside-dashboard)/new-project/page-client-parts/project-onboarding-wizard.tsx index 6ba43e318..42398e869 100644 --- a/apps/dashboard/src/app/(main)/(protected)/(outside-dashboard)/new-project/page-client-parts/project-onboarding-wizard.tsx +++ b/apps/dashboard/src/app/(main)/(protected)/(outside-dashboard)/new-project/page-client-parts/project-onboarding-wizard.tsx @@ -899,7 +899,16 @@ export function ProjectOnboardingWizard(props: { onBack={handleBack} disabled={saving} actionsLayout="inline" - primaryAction={ + primaryAction={selectedPaymentsCountry === "US" ? ( + runAsynchronouslyWithAlert(connectPaymentsSetup)} + > + Connect + + ) : ( Do Later - } + )} secondaryAction={selectedPaymentsCountry === "US" ? ( runAsynchronouslyWithAlert(connectPaymentsSetup)} + loading={paymentsSetupAction === "defer"} + onClick={() => runAsynchronouslyWithAlert(deferPaymentsSetup)} > - Connect + Do Later ) : undefined} > diff --git a/apps/dashboard/src/app/(main)/purchase/[code]/page-client.tsx b/apps/dashboard/src/app/(main)/purchase/[code]/page-client.tsx index d3937e69d..3c3342e62 100644 --- a/apps/dashboard/src/app/(main)/purchase/[code]/page-client.tsx +++ b/apps/dashboard/src/app/(main)/purchase/[code]/page-client.tsx @@ -32,6 +32,41 @@ type ProductData = { const apiUrl = getPublicEnvVar("NEXT_PUBLIC_STACK_API_URL") ?? throwErr("NEXT_PUBLIC_STACK_API_URL is not set"); const baseUrl = new URL("/api/v1", apiUrl).toString(); const MAX_STRIPE_AMOUNT_CENTS = 999_999 * 100; +const GENERIC_PURCHASE_FAILURE_MESSAGE = "We couldn't complete the purchase. Please try again."; +const GENERIC_TEST_MODE_PURCHASE_FAILURE_MESSAGE = "We couldn't complete the test purchase. Please try again."; + +async function readResponseJson(response: Response): Promise { + const text = await response.text(); + if (text.length === 0) { + return null; + } + try { + return JSON.parse(text); + } catch { + return null; + } +} + +function getResponseCode(responseBody: unknown) { + if (typeof responseBody === "object" && responseBody !== null && "code" in responseBody && typeof responseBody.code === "string") { + return responseBody.code; + } + return null; +} + +function getPurchaseFailureMessage(responseBody: unknown, fallbackMessage: string) { + if (getResponseCode(responseBody) !== null && typeof responseBody === "object" && responseBody !== null && "error" in responseBody && typeof responseBody.error === "string") { + return responseBody.error; + } + return fallbackMessage; +} + +function getClientSecret(responseBody: unknown) { + if (typeof responseBody === "object" && responseBody !== null && "client_secret" in responseBody && typeof responseBody.client_secret === "string") { + return responseBody.client_secret; + } + return null; +} export default function PageClient({ code }: { code: string }) { const [data, setData] = useState(null); @@ -126,16 +161,17 @@ export default function PageClient({ code }: { code: string }) { headers: { "Content-Type": "application/json" }, body: JSON.stringify({ full_code: code, price_id: selectedPriceId, quantity: quantityNumber }), }); - const result = await response.json(); + const result = await readResponseJson(response); if (!response.ok) { - throw new Error(result?.error?.message ?? "Failed to setup subscription"); + throw new Error(getPurchaseFailureMessage(result, GENERIC_PURCHASE_FAILURE_MESSAGE)); } - if (!result.client_secret && !isFreeSelected) { - throw new Error("Failed to setup subscription"); + const clientSecret = getClientSecret(result); + if (!clientSecret && !isFreeSelected) { + throw new Error(GENERIC_PURCHASE_FAILURE_MESSAGE); } - return result.client_secret; + return clientSecret; }; const handleBypass = useCallback(async () => { @@ -152,7 +188,8 @@ export default function PageClient({ code }: { code: string }) { }), }); if (!response.ok) { - throw new Error("Failed to bypass with test mode"); + const result = await readResponseJson(response); + throw new Error(getPurchaseFailureMessage(result, GENERIC_TEST_MODE_PURCHASE_FAILURE_MESSAGE)); } const url = new URL(`/purchase/return`, window.location.origin); url.searchParams.set("bypass", "1"); diff --git a/apps/dashboard/src/components/payments/checkout.test.tsx b/apps/dashboard/src/components/payments/checkout.test.tsx new file mode 100644 index 000000000..15bd2f7a6 --- /dev/null +++ b/apps/dashboard/src/components/payments/checkout.test.tsx @@ -0,0 +1,204 @@ +// @vitest-environment jsdom + +import type { HTMLAttributes, ReactNode } from "react"; +import { cleanup, fireEvent, render, screen, waitFor } from "@testing-library/react"; +import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; +import { CheckoutForm, TestModeBypassForm } from "./checkout"; + +const mockStripe = vi.hoisted(() => ({ + confirmPayment: vi.fn(), +})); + +const mockElements = vi.hoisted(() => ({ + submit: vi.fn(), +})); + +const alertMock = vi.hoisted(() => vi.fn()); +const locationAssignMock = vi.hoisted(() => vi.fn()); + +vi.mock("@stripe/react-stripe-js", () => ({ + PaymentElement: () =>
Payment details
, + useElements: () => mockElements, + useStripe: () => mockStripe, +})); + +vi.mock("@/components/design-components/alert", () => ({ + DesignAlert: ({ + title, + description, + className: _className, + }: { + title?: ReactNode, + description?: ReactNode, + className?: string, + }) => ( +
+ {title &&
{title}
} + {description &&
{description}
} +
+ ), +})); + +vi.mock("@/components/design-components/card", () => ({ + DesignCard: ({ children }: { children: ReactNode }) =>
{children}
, +})); + +vi.mock("@/components/ui", () => ({ + Typography: ({ children, className: _className }: { children: ReactNode } & HTMLAttributes) => ( +
{children}
+ ), +})); + +function renderCheckoutForm(props?: { + setupSubscription?: () => Promise, + isFree?: boolean, +}) { + return render( + "client-secret")} + stripeAccountId="acct_123" + fullCode="purchase-code" + disabled={false} + chargesEnabled={true} + isFree={props?.isFree ?? false} + />, + ); +} + +describe("checkout forms", () => { + beforeEach(() => { + vi.stubGlobal("alert", alertMock); + alertMock.mockReset(); + locationAssignMock.mockReset(); + Object.defineProperty(window, "location", { + configurable: true, + value: { + ...window.location, + assign: locationAssignMock, + origin: "http://localhost", + }, + }); + mockElements.submit.mockResolvedValue({}); + mockStripe.confirmPayment.mockResolvedValue({}); + }); + + afterEach(() => { + cleanup(); + vi.unstubAllGlobals(); + mockElements.submit.mockReset(); + mockStripe.confirmPayment.mockReset(); + }); + + it("shows a blocking inline error when the test-mode bypass fails", async () => { + render( + { + throw new Error("You already have this product and cannot purchase it again."); + }} + />, + ); + + fireEvent.click(screen.getByRole("button", { name: "Complete test purchase" })); + + expect(await screen.findByRole("alert")).toBeTruthy(); + expect(screen.getByText("Could not complete test purchase")).toBeTruthy(); + expect(screen.getByText("You already have this product and cannot purchase it again.")).toBeTruthy(); + expect(alertMock).not.toHaveBeenCalled(); + }); + + it("clears a stale test-mode bypass error before retrying", async () => { + const onBypass = vi.fn() + .mockRejectedValueOnce(new Error("First failure")) + .mockResolvedValueOnce(undefined); + + render(); + + fireEvent.click(screen.getByRole("button", { name: "Complete test purchase" })); + expect(await screen.findByText("First failure")).toBeTruthy(); + + fireEvent.click(screen.getByRole("button", { name: "Complete test purchase" })); + + await waitFor(() => { + expect(screen.queryByText("First failure")).toBeNull(); + }); + expect(alertMock).not.toHaveBeenCalled(); + }); + + it("shows Stripe Elements validation errors inline", async () => { + const setupSubscription = vi.fn(async () => "client-secret"); + mockElements.submit.mockResolvedValueOnce({ + error: { + message: "Enter a complete payment method.", + }, + }); + + renderCheckoutForm({ setupSubscription }); + + fireEvent.click(screen.getByRole("button", { name: "Submit" })); + + expect(await screen.findByText("Enter a complete payment method.")).toBeTruthy(); + expect(setupSubscription).not.toHaveBeenCalled(); + expect(mockStripe.confirmPayment).not.toHaveBeenCalled(); + expect(alertMock).not.toHaveBeenCalled(); + }); + + it("shows purchase-session setup errors inline", async () => { + const setupSubscription = vi.fn(async () => { + throw new Error("New purchases are currently blocked for this project."); + }); + + renderCheckoutForm({ setupSubscription }); + + fireEvent.click(screen.getByRole("button", { name: "Submit" })); + + expect(await screen.findByText("New purchases are currently blocked for this project.")).toBeTruthy(); + expect(mockStripe.confirmPayment).not.toHaveBeenCalled(); + expect(alertMock).not.toHaveBeenCalled(); + }); + + it("shows Stripe confirmation failures inline", async () => { + mockStripe.confirmPayment.mockResolvedValueOnce({ + error: { + type: "card_error", + message: "Your card was declined.", + }, + }); + + renderCheckoutForm(); + + fireEvent.click(screen.getByRole("button", { name: "Submit" })); + + expect(await screen.findByText("Your card was declined.")).toBeTruthy(); + expect(alertMock).not.toHaveBeenCalled(); + }); + + it("skips Stripe Elements for free checkout success", async () => { + const setupSubscription = vi.fn(async () => null); + + renderCheckoutForm({ setupSubscription, isFree: true }); + + expect(screen.queryByText("Payment details")).toBeNull(); + + fireEvent.click(screen.getByRole("button", { name: "Submit" })); + + await waitFor(() => { + expect(locationAssignMock).toHaveBeenCalledWith("http://localhost/purchase/return?stripe_account_id=acct_123&purchase_full_code=purchase-code&free=1"); + }); + expect(setupSubscription).toHaveBeenCalledTimes(1); + expect(mockElements.submit).not.toHaveBeenCalled(); + expect(mockStripe.confirmPayment).not.toHaveBeenCalled(); + expect(alertMock).not.toHaveBeenCalled(); + }); + + it("treats confirmPayment without an error as success", async () => { + renderCheckoutForm(); + + fireEvent.click(screen.getByRole("button", { name: "Submit" })); + + await waitFor(() => { + expect(mockStripe.confirmPayment).toHaveBeenCalledTimes(1); + }); + expect(screen.queryByText("An unexpected error occurred.")).toBeNull(); + expect(alertMock).not.toHaveBeenCalled(); + }); +}); diff --git a/apps/dashboard/src/components/payments/checkout.tsx b/apps/dashboard/src/components/payments/checkout.tsx index 5a20f1e3d..c48adf6c5 100644 --- a/apps/dashboard/src/components/payments/checkout.tsx +++ b/apps/dashboard/src/components/payments/checkout.tsx @@ -1,6 +1,7 @@ "use client"; import { DesignButton } from "@/components/design-components/button"; +import { DesignAlert } from "@/components/design-components/alert"; import { DesignCard } from "@/components/design-components/card"; import { Typography } from "@/components/ui"; import { @@ -8,7 +9,8 @@ import { useElements, useStripe, } from "@stripe/react-stripe-js"; -import { StripeError, StripePaymentElementOptions } from "@stripe/stripe-js"; +import { Result } from "@hexclave/shared/dist/utils/results"; +import { StripePaymentElementOptions } from "@stripe/stripe-js"; import { FlaskIcon, WarningCircleIcon } from "@phosphor-icons/react"; import { useState } from "react"; @@ -22,8 +24,29 @@ const paymentElementOptions = { }, } satisfies StripePaymentElementOptions; +function getErrorMessage(error: unknown, fallbackMessage: string) { + if (error instanceof Error && error.message) { + return error.message; + } + return fallbackMessage; +} + +function getStripeConfirmationError(result: unknown) { + if (typeof result !== "object" || result === null || !("error" in result)) { + return null; + } + const error = result.error; + if (typeof error !== "object" || error === null) { + return null; + } + return { + type: "type" in error && typeof error.type === "string" ? error.type : null, + message: "message" in error && typeof error.message === "string" ? error.message : null, + }; +} + type Props = { - setupSubscription: () => Promise, + setupSubscription: () => Promise, stripeAccountId: string, fullCode: string, returnUrl?: string, @@ -59,6 +82,19 @@ export function TestModeBypassForm({ onBypass: () => Promise, disabled?: boolean, }) { + const [bypassError, setBypassError] = useState(null); + const [isCompleting, setIsCompleting] = useState(false); + + const handleBypass = async () => { + setBypassError(null); + setIsCompleting(true); + const result = await Result.fromPromise(onBypass()); + if (result.status === "error") { + setBypassError(getErrorMessage(result.error, "We couldn't complete the test purchase. Please try again.")); + } + setIsCompleting(false); + }; + return (
@@ -75,12 +111,21 @@ export function TestModeBypassForm({
Complete test purchase + {bypassError && ( + + )}
); } @@ -99,15 +144,11 @@ export function CheckoutForm({ const [message, setMessage] = useState(null); const handleSubmit = async () => { - if (!stripe || !elements) { + if (!isFree && (!stripe || !elements)) { return; } - const { error: submitError } = await elements.submit(); - if (submitError) { - return setMessage(submitError.message ?? "An unexpected error occurred."); - } + setMessage(null); - const clientSecret = await setupSubscription(); const stripeReturnUrl = new URL(`/purchase/return`, window.location.origin); stripeReturnUrl.searchParams.set("stripe_account_id", stripeAccountId); stripeReturnUrl.searchParams.set("purchase_full_code", fullCode); @@ -116,6 +157,11 @@ export function CheckoutForm({ } if (isFree) { + const setupResult = await Result.fromPromise(setupSubscription()); + if (setupResult.status === "error") { + setMessage(getErrorMessage(setupResult.error, "We couldn't complete the purchase. Please try again.")); + return; + } // $0 subs: backend creates the Stripe subscription synchronously and // returns no client_secret (nothing to confirm). Skip Stripe Elements // and route through /purchase/return with `free=1` so the return page @@ -126,15 +172,49 @@ export function CheckoutForm({ window.location.assign(stripeReturnUrl.toString()); return; } - const { error } = await stripe.confirmPayment({ - elements, + + if (!stripe || !elements) { + return; + } + const activeStripe = stripe; + const activeElements = elements; + + const submitResult = await Result.fromPromise(activeElements.submit()); + if (submitResult.status === "error") { + setMessage(getErrorMessage(submitResult.error, "An unexpected error occurred.")); + return; + } + const { error: submitError } = submitResult.data; + if (submitError) { + setMessage(submitError.message ?? "An unexpected error occurred."); + return; + } + + const setupResult = await Result.fromPromise(setupSubscription()); + if (setupResult.status === "error") { + setMessage(getErrorMessage(setupResult.error, "We couldn't complete the purchase. Please try again.")); + return; + } + const clientSecret = setupResult.data; + + if (clientSecret == null) { + setMessage("We couldn't complete the purchase. Please try again."); + return; + } + const confirmResult = await Result.fromPromise(activeStripe.confirmPayment({ + elements: activeElements, clientSecret, confirmParams: { return_url: stripeReturnUrl.toString(), }, - }) as { error?: StripeError }; + })); + if (confirmResult.status === "error") { + setMessage(getErrorMessage(confirmResult.error, "An unexpected error occurred.")); + return; + } + const error = getStripeConfirmationError(confirmResult.data); - if (!error) { + if (error == null) { return; } if (error.type === "card_error" || error.type === "validation_error") { @@ -150,9 +230,9 @@ export function CheckoutForm({ return ( - + {!isFree && } diff --git a/apps/dashboard/src/components/payments/customer-payments-section.tsx b/apps/dashboard/src/components/payments/customer-payments-section.tsx index d1042bc5c..29dc14535 100644 --- a/apps/dashboard/src/components/payments/customer-payments-section.tsx +++ b/apps/dashboard/src/components/payments/customer-payments-section.tsx @@ -3,6 +3,7 @@ import { DesignBadge, type DesignBadgeColor, + DesignButton, DesignCard, } from "@/components/design-components"; import { cn, Skeleton } from "@/components/ui"; @@ -10,12 +11,13 @@ import { useAdminApp } from "@/app/(main)/(protected)/projects/[projectId]/use-a import { UserPageMetricCard } from "@/app/(main)/(protected)/projects/[projectId]/users/[userId]/user-page-metric-card"; import { UserPageTableSection } from "@/app/(main)/(protected)/projects/[projectId]/users/[userId]/user-page-table-section"; import type { Icon as PhosphorIcon } from "@phosphor-icons/react"; -import { ArrowClockwiseIcon, ArrowCounterClockwiseIcon, CoinsIcon, GearIcon, ProhibitIcon, QuestionIcon, ShoppingCartIcon, ShuffleIcon } from "@phosphor-icons/react"; +import { ArrowClockwiseIcon, ArrowCounterClockwiseIcon, CoinsIcon, GearIcon, PlusMinusIcon, ProhibitIcon, QuestionIcon, ShoppingCartIcon, ShuffleIcon } from "@phosphor-icons/react"; import type { DataGridColumnDef } from "@hexclave/dashboard-ui-components"; import type { Transaction, TransactionEntry, TransactionType } from "@hexclave/shared/dist/interface/crud/transactions"; import { captureError } from "@hexclave/shared/dist/utils/errors"; -import { Suspense, useMemo } from "react"; +import { Suspense, useMemo, useState } from "react"; import type { CustomerType } from "./customer-selector"; +import { ItemQuantityChangeDialog } from "./item-quantity-change-dialog"; // Re-export so existing consumers of this module keep working, while the // canonical definition lives in customer-selector.tsx. @@ -527,6 +529,7 @@ function ItemsCard({ customerType, customerId, itemIds }: { customerType: Custom function ItemBalanceRow({ customerType, customerId, itemId }: { customerType: CustomerType, customerId: string, itemId: string }) { const hexclaveAdminApp = useAdminApp(); + const [isAdjustOpen, setIsAdjustOpen] = useState(false); const itemOptions = customerType === "user" ? { userId: customerId, itemId } : customerType === "team" @@ -536,13 +539,36 @@ function ItemBalanceRow({ customerType, customerId, itemId }: { customerType: Cu const isNegative = item.quantity < 0; return ( -
- {item.displayName} - - {item.quantity} - -
+ <> +
+ {item.displayName} +
+ + {item.quantity} + + setIsAdjustOpen(true)} + > + + +
+
+ + ); } diff --git a/apps/dashboard/src/components/payments/item-quantity-change-dialog.tsx b/apps/dashboard/src/components/payments/item-quantity-change-dialog.tsx new file mode 100644 index 000000000..2ab965c76 --- /dev/null +++ b/apps/dashboard/src/components/payments/item-quantity-change-dialog.tsx @@ -0,0 +1,167 @@ +"use client"; + +import { useAdminApp } from "@/app/(main)/(protected)/projects/[projectId]/use-admin-app"; +import { + DesignButton, + DesignDialog, + DesignDialogClose, + DesignInput, +} from "@/components/design-components"; +import { Label, Typography, toast } from "@/components/ui"; +import { cn } from "@/lib/utils"; +import { PlusMinusIcon } from "@phosphor-icons/react"; +import { runAsynchronouslyWithAlert } from "@hexclave/shared/dist/utils/promises"; +import { Result } from "@hexclave/shared/dist/utils/results"; +import { useEffect, useState } from "react"; +import type { CustomerType } from "./customer-selector"; + +type Props = { + open: boolean, + onOpenChange: (open: boolean) => void, + customerType: CustomerType, + customerId: string, + itemId: string, + itemDisplayName: string, + currentQuantity: number, +}; + +function parseQuantityChange(text: string): number | null { + const trimmed = text.trim(); + if (!/^[+-]?\d+$/.test(trimmed)) return null; + const parsed = Number.parseInt(trimmed, 10); + if (!Number.isSafeInteger(parsed) || parsed === 0) return null; + return parsed; +} + +/** + * Dialog for creating a manual item quantity change (positive or negative + * delta) for a single customer and a single item. Opened from the item + * balances card on the customer payments views. + */ +export function ItemQuantityChangeDialog(props: Props) { + const hexclaveAdminApp = useAdminApp(); + const [quantityText, setQuantityText] = useState(""); + const [description, setDescription] = useState(""); + const [error, setError] = useState(null); + const [isSubmitting, setIsSubmitting] = useState(false); + + // Reset the form whenever the dialog is (re)opened so stale input doesn't + // leak across invocations. + useEffect(() => { + if (props.open) { + setQuantityText(""); + setDescription(""); + setError(null); + } + }, [props.open]); + + const parsedQuantity = parseQuantityChange(quantityText); + const newQuantity = parsedQuantity == null ? null : props.currentQuantity + parsedQuantity; + + const submit = async () => { + if (parsedQuantity == null) { + setError("Enter a non-zero whole number. Use a negative value to subtract."); + return; + } + setIsSubmitting(true); + try { + const customerOptions = props.customerType === "user" + ? { userId: props.customerId } + : props.customerType === "team" + ? { teamId: props.customerId } + : { customCustomerId: props.customerId }; + const result = await Result.fromPromise(hexclaveAdminApp.createItemQuantityChange({ + ...customerOptions, + itemId: props.itemId, + quantity: parsedQuantity, + ...(description.trim() ? { description: description.trim() } : {}), + })); + if (result.status === "error") { + toast({ title: "Failed to update item quantity", variant: "destructive" }); + return; + } + toast({ title: `${props.itemDisplayName}: quantity changed by ${parsedQuantity > 0 ? "+" : ""}${parsedQuantity}` }); + props.onOpenChange(false); + } finally { + setIsSubmitting(false); + } + }; + + return ( + + + + Cancel + + + runAsynchronouslyWithAlert(submit())} + > + Apply Change + + + )} + > +
+
+ + { + setQuantityText(e.target.value); + if (error) setError(null); + }} + placeholder="e.g. 10 or -5" + autoFocus + disabled={isSubmitting} + size="md" + className={cn( + "tabular-nums", + error && "border-destructive focus-visible:ring-destructive/30", + )} + /> + {error ? ( + + {error} + + ) : ( + + {newQuantity == null + ? "Positive values add to the balance, negative values subtract." + : `New balance: ${props.currentQuantity} → ${newQuantity}`} + + )} +
+ +
+ + setDescription(e.target.value)} + placeholder="e.g. Support credit for outage" + disabled={isSubmitting} + size="md" + /> +
+
+
+ ); +} diff --git a/packages/template/src/lib/hexclave-app/apps/implementations/admin-app-impl.ts b/packages/template/src/lib/hexclave-app/apps/implementations/admin-app-impl.ts index 7f1d26189..78ecdddd1 100644 --- a/packages/template/src/lib/hexclave-app/apps/implementations/admin-app-impl.ts +++ b/packages/template/src/lib/hexclave-app/apps/implementations/admin-app-impl.ts @@ -9,7 +9,7 @@ import type { AdminGetSessionReplayChunkEventsResponse } from "@hexclave/shared/ import type { Transaction, TransactionType } from "@hexclave/shared/dist/interface/crud/transactions"; import type { RestrictedReason } from "@hexclave/shared/dist/schema-fields"; import type { MoneyAmount } from "@hexclave/shared/dist/utils/currency-constants"; -import { HexclaveAssertionError, throwErr } from "@hexclave/shared/dist/utils/errors"; +import { HexclaveAssertionError, captureError, throwErr } from "@hexclave/shared/dist/utils/errors"; import type { Json } from "@hexclave/shared/dist/utils/json"; import { pick, typedEntries, typedValues } from "@hexclave/shared/dist/utils/objects"; import { Result } from "@hexclave/shared/dist/utils/results"; @@ -905,6 +905,20 @@ export class _HexclaveAdminAppImplIncomplete true); + } catch (error) { + captureError("create-item-quantity-change-cache-refresh", error); + } } async refundTransaction(options: { diff --git a/packages/template/src/lib/hexclave-app/apps/implementations/server-app-impl.ts b/packages/template/src/lib/hexclave-app/apps/implementations/server-app-impl.ts index c931ec3a0..1594e4dcc 100644 --- a/packages/template/src/lib/hexclave-app/apps/implementations/server-app-impl.ts +++ b/packages/template/src/lib/hexclave-app/apps/implementations/server-app-impl.ts @@ -1448,6 +1448,16 @@ export class _HexclaveServerAppImplIncomplete { + if (customerType === "user") { + await this._serverUserItemsCache.refresh([customerId, itemId]); + } else if (customerType === "team") { + await this._serverTeamItemsCache.refresh([customerId, itemId]); + } else { + await this._serverCustomItemsCache.refresh([customerId, itemId]); + } + } + async listProducts(options: CustomerProductsRequestOptions): Promise { if ("userId" in options) { const response = Result.orThrow(await this._serverUserProductsCache.getOrWait([options.userId, options.cursor ?? null, options.limit ?? null], "write-only"));