From 38237fe3638ef074f295f75dc4a3693cefb9eba8 Mon Sep 17 00:00:00 2001 From: Konstantin Wohlwend Date: Wed, 8 Jul 2026 15:56:59 -0700 Subject: [PATCH] Decrease BulldozerJS log spam --- apps/bulldozer-js/package.json | 2 +- .../src/databases/bulldozer/index.ts | 38 +++++---- .../low-level/implementations/lmdb.ts | 85 ++++++++++--------- .../src/databases/piledriver/index.ts | 55 ++++++------ apps/bulldozer-js/src/index.ts | 12 +-- apps/bulldozer-js/src/logging.ts | 1 + 6 files changed, 103 insertions(+), 90 deletions(-) create mode 100644 apps/bulldozer-js/src/logging.ts diff --git a/apps/bulldozer-js/package.json b/apps/bulldozer-js/package.json index a2274fb95..1f079dd62 100644 --- a/apps/bulldozer-js/package.json +++ b/apps/bulldozer-js/package.json @@ -6,7 +6,7 @@ "type": "module", "scripts": { "start": "tsx --expose-gc src/index.ts", - "dev": "tsx watch --clear-screen=false --expose-gc src/index.ts", + "dev": "NODE_ENV=development 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/src/databases/bulldozer/index.ts b/apps/bulldozer-js/src/databases/bulldozer/index.ts index 776caeca9..f22109419 100644 --- a/apps/bulldozer-js/src/databases/bulldozer/index.ts +++ b/apps/bulldozer-js/src/databases/bulldozer/index.ts @@ -1,5 +1,6 @@ import { isShallowEqual } from "@hexclave/shared/dist/utils/arrays"; import { inspect } from "node:util"; +import { shouldSuppressPeriodicBulldozerLogs } from "../../logging.js"; import { traceSpan } from "../../otel.js"; import { DatabaseSeq } from "../index.js"; import type { LowLevelDatabaseDebugSnapshot } from "../low-level/index.js"; @@ -228,6 +229,7 @@ function logSnapshotMutationDebugInfo(value: { rowsSetOrDeleted: number, debugInfo: BulldozerSnapshotMutationDebugInfo, }) { + if (shouldSuppressPeriodicBulldozerLogs) return; if (value.rowsSetOrDeleted <= 0) return; console.debug("bulldozer-js snapshot mutation", inspect(value, { depth: null, @@ -934,23 +936,25 @@ export function declareBulldozerDatabase(piledriverDatabase: PiledriverDatabase, 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 })); + if (!shouldSuppressPeriodicBulldozerLogs) { + 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; }); }; 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 8e249e9c6..62873c110 100644 --- a/apps/bulldozer-js/src/databases/low-level/implementations/lmdb.ts +++ b/apps/bulldozer-js/src/databases/low-level/implementations/lmdb.ts @@ -1,6 +1,7 @@ import { encodeBase64 } from "@hexclave/shared/dist/utils/bytes"; import { wait } from "@hexclave/shared/dist/utils/promises"; import * as lmdb from "lmdb"; +import { shouldSuppressPeriodicBulldozerLogs } from "../../../logging.js"; import { traceSpanHot } from "../../../otel.js"; import { DatabaseSeq } from "../../index.js"; import { LowLevelDatabase, LowLevelDatabaseDebugEntry, LowLevelKvDump, LowLevelKvStore } from "../index.js"; @@ -146,47 +147,49 @@ export function declareLmdbLowLevelDatabase(options: { path: string, dbId?: stri 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(); + if (!shouldSuppressPeriodicBulldozerLogs) { + 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; diff --git a/apps/bulldozer-js/src/databases/piledriver/index.ts b/apps/bulldozer-js/src/databases/piledriver/index.ts index 52e4670eb..7e6e3737d 100644 --- a/apps/bulldozer-js/src/databases/piledriver/index.ts +++ b/apps/bulldozer-js/src/databases/piledriver/index.ts @@ -1,4 +1,5 @@ import { decodeBase64, encodeBase64 } from "@hexclave/shared/dist/utils/bytes"; +import { shouldSuppressPeriodicBulldozerLogs } from "../../logging.js"; import { traceSpan, traceSpanHot } from "../../otel.js"; import { Database, DatabaseSeq } from "../index.js"; import { LowLevelDatabase, LowLevelDatabaseDebugSnapshot } from "../low-level/index.js"; @@ -659,32 +660,34 @@ export function declarePiledriverDatabase(lowLevelDb: LowLevelDatabase, options: }) .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, - }); + if (!shouldSuppressPeriodicBulldozerLogs) { + 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 d87b170df..01bbf6036 100644 --- a/apps/bulldozer-js/src/index.ts +++ b/apps/bulldozer-js/src/index.ts @@ -18,6 +18,7 @@ import { declareLmdbLowLevelDatabase } from "./databases/low-level/implementatio import type { LowLevelDatabase } from "./databases/low-level/index.js"; import { declarePiledriverDatabase, type PiledriverObject } from "./databases/piledriver/index.js"; import "./load-env.js"; +import { shouldSuppressPeriodicBulldozerLogs } from "./logging.js"; import { instrumentation, traceSpan } from "./otel.js"; import { createPaymentsSchema, itemQuantitiesLedgerUpperBoundAsOf } from "./payments/schema/index.js"; import type { CustomerType, Json, SubscriptionRow, TransactionRow } from "./payments/schema/types.js"; @@ -128,7 +129,8 @@ function serviceMemoryUsage() { }; } -function logBulldozerService(event: string, fields: Record) { +function logBulldozerService(event: string, fields: Record, options?: { suppressInNodeEnvDevelopment?: boolean }) { + if (options?.suppressInNodeEnvDevelopment === true && shouldSuppressPeriodicBulldozerLogs) return; console.log(JSON.stringify({ component: "bulldozer-js", event, @@ -283,7 +285,7 @@ async function handler(label: string, operation: () => Promise) { logBulldozerService("http-handler-start", { label, memory: serviceMemoryUsage(), - }); + }, { suppressInNodeEnvDevelopment: true }); try { const operationStartedAt = performance.now(); const body = await operation(); @@ -300,7 +302,7 @@ async function handler(label: string, operation: () => Promise) { responseSerializationMs, elapsedMs: performance.now() - startedAt, memory: serviceMemoryUsage(), - }); + }, { suppressInNodeEnvDevelopment: true }); return response; } catch (error) { if (StatusError.isStatusError(error) && error.isClientError()) { @@ -1044,7 +1046,7 @@ const startupFields = { heapGcMaxPasses: HEAP_GC_MAX_PASSES, memory: serviceMemoryUsage(), }; -logBulldozerService("service-started", startupFields); +logBulldozerService("service-started", startupFields, { suppressInNodeEnvDevelopment: true }); // Emit every boot to Sentry so restart/crash loops are visible. An OOM kill (and // most hard crashes) terminate the process before anything can be reported, so we @@ -1084,7 +1086,7 @@ runAsynchronously(async () => { slowThresholdMs: TICK_LOOP_SLOW_MS, lastTickMillis, memory: serviceMemoryUsage(), - }); + }, { suppressInNodeEnvDevelopment: true }); } await wait(1000); }); diff --git a/apps/bulldozer-js/src/logging.ts b/apps/bulldozer-js/src/logging.ts new file mode 100644 index 000000000..ca6e4c36a --- /dev/null +++ b/apps/bulldozer-js/src/logging.ts @@ -0,0 +1 @@ +export const shouldSuppressPeriodicBulldozerLogs = process.env.NODE_ENV === "development";