CodeCow/stack
1
0
Fork 0
mirror of https://github.com/stack-auth/stack.git synced 2026-07-20 21:29:36 +08:00
Code Issues Actions 2 Packages Projects Releases Wiki Activity

Decrease BulldozerJS log spam

Browse Source
This commit is contained in:
Konstantin Wohlwend 2026-07-08 15:56:59 -07:00
parent bf93740c7e
commit 38237fe363
6 changed files with 103 additions and 90 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
apps/bulldozer-js/package.json
View File

@ -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",

38
apps/bulldozer-js/src/databases/bulldozer/index.ts
View File

@ -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;
});
};

85
apps/bulldozer-js/src/databases/low-level/implementations/lmdb.ts
View File

@ -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<void> | 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;

55
apps/bulldozer-js/src/databases/piledriver/index.ts
View File

@ -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 };
});
},

12
apps/bulldozer-js/src/index.ts
View File

@ -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<string, unknown>) {
function logBulldozerService(event: string, fields: Record<string, unknown>, 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<unknown>) {
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<unknown>) {
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);
});

1
apps/bulldozer-js/src/logging.ts Normal file
View File

@ -0,0 +1 @@
export const shouldSuppressPeriodicBulldozerLogs = process.env.NODE_ENV === "development";