diff --git a/apps/server/src/bin.test.ts b/apps/server/src/bin.test.ts index a45039448131..c13c78556a7d 100644 --- a/apps/server/src/bin.test.ts +++ b/apps/server/src/bin.test.ts @@ -78,6 +78,7 @@ const makeCliTestServerConfig = (baseDir: string) => traceBatchWindowMs: 200, traceMaxBytes: 10 * 1024 * 1024, traceMaxFiles: 10, + traceSqlSlowMs: 250, otlpTracesUrl: undefined, otlpMetricsUrl: undefined, otlpExportIntervalMs: 10_000, diff --git a/apps/server/src/cli/config.test.ts b/apps/server/src/cli/config.test.ts index def63b61fafe..8a2c0c91fa18 100644 --- a/apps/server/src/cli/config.test.ts +++ b/apps/server/src/cli/config.test.ts @@ -46,6 +46,7 @@ it.layer(NodeServices.layer)("cli config resolution", (it) => { traceBatchWindowMs: 1_000, traceMaxBytes: 10 * 1024 * 1024, traceMaxFiles: 10, + traceSqlSlowMs: 250, otlpTracesUrl: undefined, otlpMetricsUrl: undefined, otlpExportIntervalMs: 10_000, diff --git a/apps/server/src/cli/config.ts b/apps/server/src/cli/config.ts index 3165ecb31677..6e8250c461f5 100644 --- a/apps/server/src/cli/config.ts +++ b/apps/server/src/cli/config.ts @@ -86,6 +86,9 @@ const EnvServerConfig = Config.all({ traceMaxBytes: Config.int("T3CODE_TRACE_MAX_BYTES").pipe(Config.withDefault(10 * 1024 * 1024)), traceMaxFiles: Config.int("T3CODE_TRACE_MAX_FILES").pipe(Config.withDefault(10)), traceBatchWindowMs: Config.int("T3CODE_TRACE_BATCH_WINDOW_MS").pipe(Config.withDefault(1_000)), + // One span per SQL statement dominates trace volume. Keep the slow ones, + // which is how a pathological query is actually found, and drop the rest. + traceSqlSlowMs: Config.int("T3CODE_TRACE_SQL_SLOW_MS").pipe(Config.withDefault(250)), otlpTracesUrl: Config.string("T3CODE_OTLP_TRACES_URL").pipe( Config.option, Config.map(Option.getOrUndefined), @@ -394,6 +397,7 @@ export const resolveServerConfig = ( traceBatchWindowMs: env.traceBatchWindowMs, traceMaxBytes: env.traceMaxBytes, traceMaxFiles: env.traceMaxFiles, + traceSqlSlowMs: env.traceSqlSlowMs, otlpTracesUrl: env.otlpTracesUrl ?? bootstrap?.otlpTracesUrl ?? diff --git a/apps/server/src/cli/pair.ts b/apps/server/src/cli/pair.ts index 231d2cbae912..d02ed1976d2f 100644 --- a/apps/server/src/cli/pair.ts +++ b/apps/server/src/cli/pair.ts @@ -330,6 +330,7 @@ const makePairServerConfig = Effect.fn(function* (input: { traceBatchWindowMs: 1_000, traceMaxBytes: 10 * 1024 * 1024, traceMaxFiles: 10, + traceSqlSlowMs: 250, otlpTracesUrl: undefined, otlpMetricsUrl: undefined, otlpExportIntervalMs: 10_000, diff --git a/apps/server/src/config.ts b/apps/server/src/config.ts index b12fafe17885..9b33d2f80f34 100644 --- a/apps/server/src/config.ts +++ b/apps/server/src/config.ts @@ -82,6 +82,11 @@ export class ServerConfig extends Context.Service< readonly traceBatchWindowMs: number; readonly traceMaxBytes: number; readonly traceMaxFiles: number; + /** + * Duration at or above which a `sql.execute` span is kept in the trace file. + * Faster successful statements are dropped at the sink; 0 keeps them all. + */ + readonly traceSqlSlowMs: number; readonly otlpTracesUrl: string | undefined; readonly otlpMetricsUrl: string | undefined; readonly otlpExportIntervalMs: number; @@ -196,6 +201,7 @@ const makeTest = Effect.fn("ServerConfig.makeTest")(function* ( traceBatchWindowMs: 200, traceMaxBytes: 10 * 1024 * 1024, traceMaxFiles: 10, + traceSqlSlowMs: 250, otlpTracesUrl: undefined, otlpMetricsUrl: undefined, otlpExportIntervalMs: 10_000, diff --git a/apps/server/src/environment/ServerEnvironment.test.ts b/apps/server/src/environment/ServerEnvironment.test.ts index 263dea0bb063..16f561a95752 100644 --- a/apps/server/src/environment/ServerEnvironment.test.ts +++ b/apps/server/src/environment/ServerEnvironment.test.ts @@ -27,6 +27,7 @@ const makeServerConfig = Effect.fn(function* (baseDir: string) { traceBatchWindowMs: 200, traceMaxBytes: 10 * 1024 * 1024, traceMaxFiles: 10, + traceSqlSlowMs: 250, otlpTracesUrl: undefined, otlpMetricsUrl: undefined, otlpExportIntervalMs: 10_000, diff --git a/apps/server/src/observability/Layers/Observability.ts b/apps/server/src/observability/Layers/Observability.ts index 8aac0927534b..7ea0243282c4 100644 --- a/apps/server/src/observability/Layers/Observability.ts +++ b/apps/server/src/observability/Layers/Observability.ts @@ -1,5 +1,11 @@ import { httpHeaderRedactionLayer } from "@t3tools/shared/httpObservability"; -import { makeLocalFileTracer, makeTraceSink } from "@t3tools/shared/observability"; +// T3-CUSTOM(expbkt3): BEGIN - pull in the sink-level SQL span filter. +import { + makeLocalFileTracer, + makeTraceSink, + retainSlowSqlSpans, +} from "@t3tools/shared/observability"; +// T3-CUSTOM(expbkt3): END import * as Effect from "effect/Effect"; import * as Layer from "effect/Layer"; import * as References from "effect/References"; @@ -34,6 +40,9 @@ export const ObservabilityLive = Layer.unwrap( maxBytes: config.traceMaxBytes, maxFiles: config.traceMaxFiles, batchWindowMs: config.traceBatchWindowMs, + // T3-CUSTOM(expbkt3): BEGIN - one span per SQL statement dominated trace volume. + retain: retainSlowSqlSpans(config.traceSqlSlowMs), + // T3-CUSTOM(expbkt3): END onFlush: (stats) => attribution.record({ component: "server-trace", diff --git a/apps/server/src/orchestration/ownershipBackfill.test.ts b/apps/server/src/orchestration/ownershipBackfill.test.ts index 53ccc13616c1..ac87c8c28928 100644 --- a/apps/server/src/orchestration/ownershipBackfill.test.ts +++ b/apps/server/src/orchestration/ownershipBackfill.test.ts @@ -4,7 +4,11 @@ import * as Effect from "effect/Effect"; import * as SqlClient from "effect/unstable/sql/SqlClient"; import { SqlitePersistenceMemory } from "../persistence/Layers/Sqlite.ts"; -import { backfillProjectionOwnership } from "./ownershipBackfill.ts"; +import { + ADMIN_REASSIGNMENT_MARKER, + backfillProjectionOwnership, + planOwnershipBackfill, +} from "./ownershipBackfill.ts"; const DEFAULT_OWNER = UserId.make("user_default_owner"); const HISTORICAL_ASSIGNEE = UserId.make("user_historical_assignee"); @@ -199,3 +203,94 @@ it.layer(SqlitePersistenceMemory)("ownership backfill", (it) => { }), ); }); + +it.layer(SqlitePersistenceMemory)("ownership backfill planning", (it) => { + /** Each case owns the whole table set, so state never leaks between them. */ + const seed = Effect.fn(function* (options: { + readonly ownerUserId: string | null; + readonly repairRecorded: boolean; + }) { + const sql = yield* SqlClient.SqlClient; + yield* sql`DELETE FROM projection_threads`; + yield* sql`DELETE FROM projection_projects`; + yield* sql`DELETE FROM maintenance_markers`; + yield* sql` + INSERT INTO projection_projects ( + project_id, title, workspace_root, scripts_json, created_at, updated_at, owner_user_id + ) VALUES ( + 'project-plan', 'Planned project', '/tmp/plan', '[]', ${NOW}, ${NOW}, + ${options.ownerUserId} + ) + `; + yield* sql` + INSERT INTO projection_threads ( + thread_id, project_id, title, created_at, updated_at, owner_user_id + ) VALUES ( + 'thread-plan', 'project-plan', 'Planned thread', ${NOW}, ${NOW}, ${options.ownerUserId} + ) + `; + if (options.repairRecorded) { + yield* sql` + INSERT INTO maintenance_markers (marker, completed_at) + VALUES (${ADMIN_REASSIGNMENT_MARKER}, ${NOW}) + `; + } + }); + + it.effect("skips every scan once the repair is recorded and no row is ownerless", () => + Effect.gen(function* () { + yield* seed({ ownerUserId: DEFAULT_OWNER, repairRecorded: true }); + + assert.deepEqual(yield* planOwnershipBackfill(), { + skip: true, + repairAdminAssignments: false, + }); + }), + ); + + it.effect("still converges ownerless rows after the repair is recorded", () => + Effect.gen(function* () { + yield* seed({ ownerUserId: null, repairRecorded: true }); + + assert.deepEqual(yield* planOwnershipBackfill(), { + skip: false, + repairAdminAssignments: false, + }); + }), + ); + + it.effect("runs the admin repair exactly while its marker is missing", () => + Effect.gen(function* () { + yield* seed({ ownerUserId: DEFAULT_OWNER, repairRecorded: false }); + + assert.deepEqual(yield* planOwnershipBackfill(), { + skip: false, + repairAdminAssignments: true, + }); + }), + ); + + it.effect("leaves administrator-owned rows alone when the repair is disabled", () => + Effect.gen(function* () { + const sql = yield* SqlClient.SqlClient; + yield* seed({ ownerUserId: DEFAULT_OWNER, repairRecorded: true }); + // A historical member that the repair pass would have promoted. + yield* sql` + INSERT INTO projection_thread_members ( + thread_id, user_id, added_by_user_id, added_at + ) VALUES ( + 'thread-plan', ${HISTORICAL_ASSIGNEE}, NULL, ${NOW} + ) + `; + + yield* backfillProjectionOwnership(DEFAULT_OWNER, { repairAdminAssignments: false }); + + const threads = yield* sql<{ readonly ownerUserId: string | null }>` + SELECT owner_user_id AS "ownerUserId" + FROM projection_threads + WHERE thread_id = 'thread-plan' + `; + assert.deepEqual(threads, [{ ownerUserId: DEFAULT_OWNER }]); + }), + ); +}); diff --git a/apps/server/src/orchestration/ownershipBackfill.ts b/apps/server/src/orchestration/ownershipBackfill.ts index 1cc2fe6065b4..58d65415d6da 100644 --- a/apps/server/src/orchestration/ownershipBackfill.ts +++ b/apps/server/src/orchestration/ownershipBackfill.ts @@ -1,26 +1,55 @@ /** * ownershipBackfill - One-time legacy ownership assignment for team mode. * - * Runs at startup (after migrations) only when Clerk team mode is configured. - * Restores a creator from durable events or legacy membership first, then - * assigns any remaining ownerless thread/project to the configured default or - * earliest active administrator. Idempotent and fail-soft: if the fallback - * owner cannot be resolved it logs a warning and converges on a later boot. + * Runs after startup (once migrations have applied) only when Clerk team mode + * is configured. Restores a creator from durable events or legacy membership + * first, then assigns any remaining ownerless thread/project to the configured + * default or earliest active administrator. Idempotent and fail-soft: if the + * fallback owner cannot be resolved it logs a warning and converges on a later + * boot. + * + * T3-CUSTOM(expbkt3): the admin-reassignment repair is a one-time migration + * concern, so it is gated on a durable marker rather than re-run every boot. + * Without that gate every admin-owned row is re-scanned forever, which cost + * bkt3.dev ~146 s of blocked readiness on each restart. * * @module ownershipBackfill */ import type { UserId } from "@t3tools/contracts"; +import * as DateTime from "effect/DateTime"; import * as Effect from "effect/Effect"; import * as SqlClient from "effect/unstable/sql/SqlClient"; import { ClerkDirectory } from "../auth/ClerkDirectory.ts"; import { ServerConfig } from "../config.ts"; +/** + * Durable marker name for the one-time repair of rows bulk-assigned to the + * environment administrator before ownership was recorded on events. + */ +export const ADMIN_REASSIGNMENT_MARKER = "ownership.admin-reassignment"; + +export interface BackfillProjectionOwnershipOptions { + /** + * When true the hot WHERE clauses also re-select rows already owned by the + * administrator, so a historical bulk assignment can be replaced by the real + * creator. Expensive, and only ever correct once per database. + */ + readonly repairAdminAssignments?: boolean; +} + /** Assigns every collaborative projection a deterministic durable owner. */ export const backfillProjectionOwnership = Effect.fn("backfillProjectionOwnership")(function* ( adminUserId: UserId, + options: BackfillProjectionOwnershipOptions = {}, ) { const sql = yield* SqlClient.SqlClient; + // Rows already owned by the admin are only revisited while the one-time + // repair is outstanding; afterwards ownerless rows are the entire work set. + const needsOwner = + options.repairAdminAssignments === false + ? sql`owner_user_id IS NULL` + : sql`(owner_user_id IS NULL OR owner_user_id = ${adminUserId})`; // Prefer the actor recorded by modern created events. This repairs a stale // projection without rewriting event history. @@ -35,7 +64,7 @@ export const backfillProjectionOwnership = Effect.fn("backfillProjectionOwnershi ORDER BY created.stream_version ASC LIMIT 1 ) - WHERE (owner_user_id IS NULL OR owner_user_id = ${adminUserId}) + WHERE ${needsOwner} AND NOT EXISTS ( SELECT 1 FROM orchestration_events AS transferred @@ -61,7 +90,7 @@ export const backfillProjectionOwnership = Effect.fn("backfillProjectionOwnershi ORDER BY created.stream_version ASC LIMIT 1 ) - WHERE (owner_user_id IS NULL OR owner_user_id = ${adminUserId}) + WHERE ${needsOwner} AND NOT EXISTS ( SELECT 1 FROM orchestration_events AS transferred @@ -89,7 +118,7 @@ export const backfillProjectionOwnership = Effect.fn("backfillProjectionOwnershi ORDER BY member.added_at ASC, member.user_id ASC LIMIT 1 ) - WHERE (owner_user_id IS NULL OR owner_user_id = ${adminUserId}) + WHERE ${needsOwner} AND NOT EXISTS ( SELECT 1 FROM orchestration_events AS transferred @@ -113,7 +142,7 @@ export const backfillProjectionOwnership = Effect.fn("backfillProjectionOwnershi ORDER BY member.added_at ASC, member.user_id ASC LIMIT 1 ) - WHERE (owner_user_id IS NULL OR owner_user_id = ${adminUserId}) + WHERE ${needsOwner} AND NOT EXISTS ( SELECT 1 FROM orchestration_events AS transferred @@ -195,6 +224,60 @@ export const backfillProjectionOwnership = Effect.fn("backfillProjectionOwnershi }; }); +/** True once the named one-time repair has been recorded as complete. */ +const hasMaintenanceMarker = Effect.fn("hasMaintenanceMarker")(function* (marker: string) { + const sql = yield* SqlClient.SqlClient; + const rows = yield* sql<{ readonly marker: string }>` + SELECT marker FROM maintenance_markers WHERE marker = ${marker} LIMIT 1 + `; + return rows.length > 0; +}); + +const recordMaintenanceMarker = Effect.fn("recordMaintenanceMarker")(function* (marker: string) { + const sql = yield* SqlClient.SqlClient; + const completedAt = DateTime.formatIso(yield* DateTime.now); + yield* sql` + INSERT INTO maintenance_markers (marker, completed_at) + VALUES (${marker}, ${completedAt}) + ON CONFLICT(marker) DO NOTHING + `; +}); + +export interface OwnershipBackfillPlan { + /** Nothing to converge: skip the event-log scans entirely. */ + readonly skip: boolean; + /** Whether the one-time admin-reassignment repair is still outstanding. */ + readonly repairAdminAssignments: boolean; +} + +/** + * Decides, cheaply, whether a full backfill pass is worth running. + * + * Steady state is "every projection already has an owner and the one-time + * admin-reassignment repair is recorded". Both halves are two small projection + * scans, so the expensive correlated subqueries over the event log only run + * when there is actually something to converge. + */ +export const planOwnershipBackfill = Effect.fn("planOwnershipBackfill")(function* () { + const sql = yield* SqlClient.SqlClient; + const repairAdminAssignments = !(yield* hasMaintenanceMarker(ADMIN_REASSIGNMENT_MARKER)); + const [ownerless] = yield* sql<{ + readonly ownerlessThreads: number; + readonly ownerlessProjects: number; + }>` + SELECT + EXISTS (SELECT 1 FROM projection_threads WHERE owner_user_id IS NULL) AS "ownerlessThreads", + EXISTS (SELECT 1 FROM projection_projects WHERE owner_user_id IS NULL) AS "ownerlessProjects" + `; + const hasOwnerlessRows = + ownerless === undefined || ownerless.ownerlessThreads > 0 || ownerless.ownerlessProjects > 0; + + return { + skip: !repairAdminAssignments && !hasOwnerlessRows, + repairAdminAssignments, + } satisfies OwnershipBackfillPlan; +}); + export const runOwnershipBackfill = Effect.gen(function* () { const config = yield* ServerConfig; const clerkAuth = config.clerkAuth; @@ -203,8 +286,15 @@ export const runOwnershipBackfill = Effect.gen(function* () { return; } - const clerkDirectory = yield* ClerkDirectory; const sql = yield* SqlClient.SqlClient; + const plan = yield* planOwnershipBackfill(); + + if (plan.skip) { + yield* Effect.logDebug("ownership backfill skipped: every projection already has an owner"); + return; + } + + const clerkDirectory = yield* ClerkDirectory; const explicitOwnerId = clerkAuth.defaultOwnerUserId !== undefined ? (clerkAuth.defaultOwnerUserId as UserId) : null; const configuredAdminUserId: UserId | null = @@ -236,10 +326,19 @@ export const runOwnershipBackfill = Effect.gen(function* () { return; } - const result = yield* backfillProjectionOwnership(adminUserId); + const result = yield* backfillProjectionOwnership(adminUserId, { + repairAdminAssignments: plan.repairAdminAssignments, + }); + + // Only durable once the repair actually ran to completion; a failure leaves + // the marker absent so the next boot retries. + if (plan.repairAdminAssignments) { + yield* recordMaintenanceMarker(ADMIN_REASSIGNMENT_MARKER); + } yield* Effect.logInfo("ownership backfill complete", { adminUserId, + repairedAdminAssignments: plan.repairAdminAssignments, ...result, }); }).pipe( diff --git a/apps/server/src/persistence/Layers/Sqlite.ts b/apps/server/src/persistence/Layers/Sqlite.ts index d1e002501263..363e41be6342 100644 --- a/apps/server/src/persistence/Layers/Sqlite.ts +++ b/apps/server/src/persistence/Layers/Sqlite.ts @@ -35,6 +35,25 @@ const setup = Layer.effectDiscard( const sql = yield* SqlClient.SqlClient; yield* sql`PRAGMA foreign_keys = ON;`; yield* sql`PRAGMA journal_mode = WAL;`; + // T3-CUSTOM(expbkt3): BEGIN + // SQLite's defaults are tuned for a small database on a private disk. Ours + // is multi-gigabyte and shared, so the defaults cost roughly two orders of + // magnitude more physical IO than the logical data written. + // + // NORMAL cannot corrupt a WAL database: recovery replays the WAL on open. + // The only exposure is losing the last few committed transactions to a + // power cut or kernel panic; a clean process restart or crash loses + // nothing. FULL instead fsyncs on every COMMIT. + yield* sql`PRAGMA synchronous = NORMAL;`; + // The default 1000-page (~4 MB) autocheckpoint copies WAL frames back into + // the main database constantly, so every byte is written at least twice. + yield* sql`PRAGMA wal_autocheckpoint = 10000;`; + // 64 MB of page cache keeps the hot projection and event pages resident. + yield* sql`PRAGMA cache_size = -65536;`; + // Truncate the WAL back to 64 MB after a checkpoint instead of letting it + // grow to whatever the largest transaction needed. + yield* sql`PRAGMA journal_size_limit = 67108864;`; + // T3-CUSTOM(expbkt3): END yield* runMigrations(); }), ); diff --git a/apps/server/src/persistence/Migrations.ts b/apps/server/src/persistence/Migrations.ts index e862f7b80457..87ae5d92a34e 100644 --- a/apps/server/src/persistence/Migrations.ts +++ b/apps/server/src/persistence/Migrations.ts @@ -74,6 +74,9 @@ import Migration1003 from "./Migrations/1003_DurableExecutionIntents.ts"; import Migration1004 from "./Migrations/1004_ProjectionThreadsLinearIssue.ts"; // T3-CUSTOM(expbkt3): connected-client build identity for stale-bundle diagnosis. import Migration1006 from "./Migrations/1006_AuthSessionClientVersion.ts"; +// T3-CUSTOM(expbkt3): event-type index plus one-time maintenance markers so the +// ownership backfill stops re-scanning the event log on every boot. +import Migration1007 from "./Migrations/1007_OwnershipBackfillFastPath.ts"; /** * Migration loader with all migrations defined inline. @@ -159,6 +162,7 @@ const migrationEntries = [ [1004, "ProjectionThreadsLinearIssue", Migration1004], [1005, "ProjectionThreadsPinned", Migration1005], [1006, "AuthSessionClientVersion", Migration1006], + [1007, "OwnershipBackfillFastPath", Migration1007], ] as const; export const migrationManifest = migrationEntries.map(([id, name]) => [id, name] as const); diff --git a/apps/server/src/persistence/Migrations/1007_OwnershipBackfillFastPath.ts b/apps/server/src/persistence/Migrations/1007_OwnershipBackfillFastPath.ts new file mode 100644 index 000000000000..000bbcd86270 --- /dev/null +++ b/apps/server/src/persistence/Migrations/1007_OwnershipBackfillFastPath.ts @@ -0,0 +1,25 @@ +// T3-CUSTOM(expbkt3): make the startup ownership backfill cheap. +// +// The backfill's correlated subqueries filter orchestration_events on +// event_type and join on stream_id. Every existing index leads with +// aggregate_kind, so those subqueries scanned the whole event log once per +// candidate row. The marker table lets the one-time admin-reassignment repair +// record that it is done instead of re-running on every boot forever. +import * as Effect from "effect/Effect"; +import * as SqlClient from "effect/unstable/sql/SqlClient"; + +export default Effect.gen(function* () { + const sql = yield* SqlClient.SqlClient; + + yield* sql` + CREATE INDEX IF NOT EXISTS idx_orchestration_events_event_type_stream + ON orchestration_events(event_type, stream_id) + `; + + yield* sql` + CREATE TABLE IF NOT EXISTS maintenance_markers ( + marker TEXT PRIMARY KEY, + completed_at TEXT NOT NULL + ) + `; +}); diff --git a/apps/server/src/server.test.ts b/apps/server/src/server.test.ts index dd9d787235c2..e968a08402c8 100644 --- a/apps/server/src/server.test.ts +++ b/apps/server/src/server.test.ts @@ -449,6 +449,7 @@ const buildAppUnderTest = (options?: { traceBatchWindowMs: 200, traceMaxBytes: 10 * 1024 * 1024, traceMaxFiles: 10, + traceSqlSlowMs: 250, otlpTracesUrl: undefined, otlpMetricsUrl: undefined, otlpExportIntervalMs: 10_000, diff --git a/apps/server/src/serverRuntimeStartup.ts b/apps/server/src/serverRuntimeStartup.ts index 3b71978a4346..a2b1ec0b7904 100644 --- a/apps/server/src/serverRuntimeStartup.ts +++ b/apps/server/src/serverRuntimeStartup.ts @@ -378,11 +378,16 @@ export const make = (options?: StartupOptions) => ), ); - // Team mode only: converge pre-ownership records before commands open. + // Team mode only: converge pre-ownership records. This is idempotent and + // fail-soft, so it is parked alongside the other auxiliary roots rather + // than holding readiness — a full pass once cost bkt3.dev ~146 s of + // blocked startup on every restart. yield* Effect.logDebug("startup phase: ownership backfill"); - yield* runStartupPhase( - "ownership.backfill", - runOwnershipBackfill.pipe(Effect.provide(ClerkDirectoryLive)), + yield* forkParked( + runStartupPhase( + "ownership.backfill", + runOwnershipBackfill.pipe(Effect.provide(ClerkDirectoryLive)), + ), ); const welcomeBase = yield* resolveWelcomeBase; diff --git a/docs/operations/observability.md b/docs/operations/observability.md index 786da8e4be05..f54ed4b75f91 100644 --- a/docs/operations/observability.md +++ b/docs/operations/observability.md @@ -544,6 +544,10 @@ Local trace file: - `T3CODE_TRACE_BATCH_WINDOW_MS`: flush window, default `200` - `T3CODE_TRACE_MIN_LEVEL`: minimum trace level, default `Info` - `T3CODE_TRACE_TIMING_ENABLED`: enable timing metadata, default `true` +- `T3CODE_TRACE_SQL_SLOW_MS`: keep `sql.execute` spans at or above this duration + and drop the faster successful ones, default `250`. Set `0` to record every + statement — useful for a short profiling window, but one span per statement is + the largest single source of trace bytes, so do not leave it on. OTLP export: diff --git a/packages/shared/src/observability.test.ts b/packages/shared/src/observability.test.ts index 4bd1070bf1f1..0dfe5148dd8f 100644 --- a/packages/shared/src/observability.test.ts +++ b/packages/shared/src/observability.test.ts @@ -19,6 +19,9 @@ import { errorTag, makeLocalFileTracer, makeTraceSink, + retainSlowSqlSpans, + SQL_EXECUTE_SPAN_NAME, + type EffectTraceRecord, type TraceRecord, type TraceSinkFlushStats, } from "./observability.ts"; @@ -85,6 +88,34 @@ const makeRecord = (name: string, suffix = ""): TraceRecord => ({ }, }); +const makeSqlRecord = ( + durationMs: number, + exit: EffectTraceRecord["exit"] = { _tag: "Success" }, +): TraceRecord => ({ + ...(makeRecord(SQL_EXECUTE_SPAN_NAME, `${durationMs}`) as EffectTraceRecord), + durationMs, + exit, +}); + +describe("retainSlowSqlSpans", () => { + const retain = retainSlowSqlSpans(250); + + it("drops fast successful statements and keeps slow or failed ones", () => { + assert.equal(retain(makeSqlRecord(4)), false); + assert.equal(retain(makeSqlRecord(250)), true); + assert.equal(retain(makeSqlRecord(97_900)), true); + assert.equal(retain(makeSqlRecord(4, { _tag: "Failure", cause: "boom" })), true); + }); + + it("never touches spans that are not SQL statements", () => { + assert.equal(retain(makeRecord("server.startup.ownership.backfill")), true); + }); + + it("retains everything when the threshold is disabled", () => { + assert.equal(retainSlowSqlSpans(0)(makeSqlRecord(4)), true); + }); +}); + const readTraceRecords = Effect.fn("readTraceRecords")(function* (tracePath: string) { const fileSystem = yield* FileSystem.FileSystem; return (yield* fileSystem.readFileString(tracePath)) @@ -178,6 +209,37 @@ describe("observability", () => { ), ); + it.effect("never buffers records the retain predicate rejects", () => + Effect.scoped( + Effect.gen(function* () { + const fileSystem = yield* FileSystem.FileSystem; + const path = yield* Path.Path; + const tempDir = yield* fileSystem.makeTempDirectoryScoped({ prefix: "t3-trace-sink-" }); + const tracePath = path.join(tempDir, "shared.trace.ndjson"); + + const sink = yield* makeTraceSink({ + filePath: tracePath, + maxBytes: 1024, + maxFiles: 2, + batchWindowMs: 10_000, + retain: retainSlowSqlSpans(250), + }); + + sink.push(makeSqlRecord(4)); + sink.push(makeSqlRecord(400)); + sink.push(makeRecord("server.startup")); + yield* sink.close(); + + const lines = yield* readTraceRecords(tracePath); + + assert.deepEqual( + lines.map((line) => line.name), + [SQL_EXECUTE_SPAN_NAME, "server.startup"], + ); + }), + ), + ); + it.effect("reports successful logical trace writes", () => Effect.scoped( Effect.gen(function* () { diff --git a/packages/shared/src/observability.ts b/packages/shared/src/observability.ts index e0a7595865d9..c019e1733e13 100644 --- a/packages/shared/src/observability.ts +++ b/packages/shared/src/observability.ts @@ -111,8 +111,44 @@ export interface TraceSinkOptions { readonly maxFiles: number; readonly batchWindowMs: number; readonly onFlush?: (stats: TraceSinkFlushStats) => Effect.Effect; + // T3-CUSTOM(expbkt3): BEGIN + /** + * Decides whether a record is worth persisting. Records rejected here never + * reach the buffer, so a high-volume span kind can be dropped without raising + * the tracer's minimum level and blinding every other span. + */ + readonly retain?: (record: TraceRecord) => boolean; + // T3-CUSTOM(expbkt3): END } +// T3-CUSTOM(expbkt3): BEGIN +/** Span name the Effect SQL client uses for every executed statement. */ +export const SQL_EXECUTE_SPAN_NAME = "sql.execute"; + +function isFailedTraceRecord(record: TraceRecord): boolean { + return record.type === "effect-span" + ? record.exit._tag !== "Success" + : record.status?.code !== undefined && record.status.code !== "Ok"; +} + +/** + * Retains everything except fast, successful `sql.execute` spans. + * + * One statement per span at Info level is the single largest source of trace + * bytes in a server, but the slow ones are exactly how a pathological query is + * found, so anything at or above `slowMs` is kept — as are failures, which the + * diagnostics dashboard counts. A non-positive `slowMs` disables the filter. + */ +export const retainSlowSqlSpans = + (slowMs: number) => + (record: TraceRecord): boolean => { + if (slowMs <= 0 || record.name !== SQL_EXECUTE_SPAN_NAME) { + return true; + } + return record.durationMs >= slowMs || isFailedTraceRecord(record); + }; +// T3-CUSTOM(expbkt3): END + export interface TraceSinkFlushStats { readonly logicalWriteBytes: number; readonly count: number; @@ -359,6 +395,11 @@ export const makeTraceSink = Effect.fn("makeTraceSink")(function* (options: Trac return { filePath: options.filePath, push(record) { + // T3-CUSTOM(expbkt3): BEGIN - drop low-value spans before they reach the buffer. + if (options.retain !== undefined && !options.retain(record)) { + return; + } + // T3-CUSTOM(expbkt3): END try { buffer.push(`${JSON.stringify(record)}\n`); if (buffer.length >= FLUSH_BUFFER_THRESHOLD) {