| author | |
| committer | |
| log | 28732b4787261609c4d20b82b244cb6eef0c442e |
| tree | 86101d5a59b28df9a657ea8cbe6578d5a45d3226 |
| parent | 36f91c45687f97fc8e12ff89eaa8cff6f23abe8b |
| signature | Signed by PGP key B5690EEEBB952194 |
Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>6 files changed, 340 insertions(+), 30 deletions(-)
apps/server/src/observability/EventLoopMonitor.test.ts+75-6| ... | ... | @@ -1,6 +1,9 @@ |
| 1 | import * as NodeServices from "@effect/platform-node/NodeServices"; | |
| 1 | 2 | import { assert, describe, it } from "@effect/vitest"; |
| 2 | 3 | import * as Effect from "effect/Effect"; |
| 4 | import * as FileSystem from "effect/FileSystem"; | |
| 3 | 5 | import * as Layer from "effect/Layer"; |
| 6 | import * as Logger from "effect/Logger"; | |
| 4 | 7 | import * as Tracer from "effect/Tracer"; |
| 5 | 8 | import * as TestClock from "effect/testing/TestClock"; |
| 6 | 9 | |
| ... | ... | @@ -25,6 +28,18 @@ const stalled: EventLoopMonitor.EventLoopReadings = { |
| 25 | 28 | // Over the threshold as read, but not once the resolution is subtracted. |
| 26 | 29 | const quiet: EventLoopMonitor.EventLoopReadings = { ...stalled, delayMaxNs: ms(2_950) }; |
| 27 | 30 | |
| 31 | // The first sample covers startup, so the monitor discards it. | |
| 32 | const monitor = ( | |
| 33 | samples: Array<EventLoopMonitor.EventLoopReadings>, | |
| 34 | stallLog: EventLoopMonitor.StallLogOptions = { filePath: "\0", maxBytes: 1 }, | |
| 35 | ) => | |
| 36 | Layer.build( | |
| 37 | EventLoopMonitor.layerWith( | |
| 38 | Effect.succeed(Effect.sync(() => samples.shift() ?? quiet)), | |
| 39 | stallLog, | |
| 40 | ), | |
| 41 | ); | |
| 42 | ||
| 28 | 43 | describe("EventLoopMonitor", () => { |
| 29 | 44 | it.effect("records a warning span only for samples that saw a stall", () => |
| 30 | 45 | Effect.gen(function* () { |
| ... | ... | @@ -36,13 +51,9 @@ describe("EventLoopMonitor", () => { |
| 36 | 51 | return span; |
| 37 | 52 | }, |
| 38 | 53 | }); |
| 39 | // The first sample covers startup, so the monitor discards it. | |
| 40 | const samples = [stalled, quiet, stalled]; | |
| 41 | ||
| 42 | 54 | yield* Effect.gen(function* () { |
| 43 | yield* Layer.build( | |
| 44 | EventLoopMonitor.layerWith(Effect.succeed(Effect.sync(() => samples.shift() ?? quiet))), | |
| 45 | ); | |
| 55 | // The default stall log path cannot open, and the span must still be recorded. | |
| 56 | yield* monitor([stalled, quiet, stalled]); | |
| 46 | 57 | yield* TestClock.adjust("60 seconds"); |
| 47 | 58 | assert.lengthOf(spans, 0); |
| 48 | 59 | yield* TestClock.adjust("30 seconds"); |
| ... | ... | @@ -70,6 +81,64 @@ describe("EventLoopMonitor", () => { |
| 70 | 81 | }), |
| 71 | 82 | ); |
| 72 | 83 | |
| 84 | it.effect("keeps each stall as one line in a capped stall log", () => | |
| 85 | Effect.gen(function* () { | |
| 86 | const fs = yield* FileSystem.FileSystem; | |
| 87 | const directory = yield* fs.makeTempDirectoryScoped({ prefix: "t3-event-loop-" }); | |
| 88 | const filePath = `${directory}/event-loop-stalls.ndjson`; | |
| 89 | // Room for one line, so each new stall rotates the last one into the backup. | |
| 90 | yield* monitor([stalled, stalled, stalled, { ...stalled, delayMaxNs: ms(7_000) }], { | |
| 91 | filePath, | |
| 92 | maxBytes: 300, | |
| 93 | }); | |
| 94 | yield* TestClock.adjust("120 seconds"); | |
| 95 | ||
| 96 | const lines = (yield* fs.readFileString(filePath)).trim().split("\n"); | |
| 97 | assert.deepStrictEqual( | |
| 98 | lines.map((line) => JSON.parse(line)), | |
| 99 | [ | |
| 100 | { | |
| 101 | time: "1970-01-01T00:02:00.000Z", | |
| 102 | delayMaxMs: 6_000, | |
| 103 | utilization: 0.18, | |
| 104 | cpuUserMs: 310, | |
| 105 | cpuSystemMs: 96, | |
| 106 | majorPageFaults: 8_412, | |
| 107 | minorPageFaults: 20_031, | |
| 108 | involuntaryContextSwitches: 57, | |
| 109 | rssMb: 1536, | |
| 110 | }, | |
| 111 | ], | |
| 112 | ); | |
| 113 | assert.lengthOf((yield* fs.readFileString(`${filePath}.1`)).trim().split("\n"), 1); | |
| 114 | assert.isFalse(yield* fs.exists(`${filePath}.2`)); | |
| 115 | }).pipe(Effect.scoped, Effect.provide(NodeServices.layer)), | |
| 116 | ); | |
| 117 | ||
| 118 | it.effect("warns when a stall cannot be written to the stall log", () => { | |
| 119 | const warnings: Array<unknown> = []; | |
| 120 | const logger = Logger.make(({ message }) => { | |
| 121 | warnings.push(Array.isArray(message) ? message[0] : message); | |
| 122 | }); | |
| 123 | return Effect.gen(function* () { | |
| 124 | const fs = yield* FileSystem.FileSystem; | |
| 125 | // A directory at the log path opens, but every append to it fails. The cap | |
| 126 | // is large so the sink never rotates the directory out of the way. | |
| 127 | const filePath = yield* fs.makeTempDirectoryScoped({ prefix: "t3-event-loop-" }); | |
| 128 | yield* monitor([stalled, stalled], { filePath, maxBytes: 1024 * 1024 }); | |
| 129 | yield* TestClock.adjust("60 seconds"); | |
| 130 | assert.deepStrictEqual(warnings, [ | |
| 131 | "event loop stalled for 4950 ms", | |
| 132 | "event loop stall log write failed", | |
| 133 | ]); | |
| 134 | }).pipe( | |
| 135 | Effect.scoped, | |
| 136 | Effect.provide( | |
| 137 | Layer.merge(NodeServices.layer, Logger.layer([logger], { mergeWithExisting: false })), | |
| 138 | ), | |
| 139 | ); | |
| 140 | }); | |
| 141 | ||
| 73 | 142 | it("ignores delay the loop spent idle, such as a system sleep", () => { |
| 74 | 143 | // Waking from sleep reads as a long gap, but the loop was idle in poll for it. |
| 75 | 144 | const asleep: EventLoopMonitor.EventLoopReadings = { |
apps/server/src/observability/EventLoopMonitor.ts+70-17| ... | ... | @@ -1,10 +1,16 @@ |
| 1 | 1 | // @effect-diagnostics nodeBuiltinImport:off - only node:perf_hooks exposes the event loop delay histogram. |
| 2 | 2 | import * as NodePerfHooks from "node:perf_hooks"; |
| 3 | 3 | |
| 4 | import { RotatingFileSink } from "@t3tools/shared/logging"; | |
| 5 | import * as DateTime from "effect/DateTime"; | |
| 4 | 6 | import * as Effect from "effect/Effect"; |
| 5 | 7 | import * as Layer from "effect/Layer"; |
| 8 | import * as Path from "effect/Path"; | |
| 9 | import * as Schema from "effect/Schema"; | |
| 6 | 10 | import type * as Scope from "effect/Scope"; |
| 7 | 11 | |
| 12 | import * as ServerConfig from "../config.ts"; | |
| 13 | ||
| 8 | 14 | // Node's delay histogram wakes a native timer every RESOLUTION_MS and records the |
| 9 | 15 | // gap between wakeups, so an idle loop reads about RESOLUTION_MS and a stall of S |
| 10 | 16 | // reads between S and S + RESOLUTION_MS. We subtract the resolution, so a delay can |
| ... | ... | @@ -13,6 +19,9 @@ import type * as Scope from "effect/Scope"; |
| 13 | 19 | const RESOLUTION_MS = 1000; |
| 14 | 20 | const STALL_THRESHOLD_MS = 2000; |
| 15 | 21 | const SAMPLE_INTERVAL = "30 seconds"; |
| 22 | // A stall line is about 250 bytes, so the file and its one backup keep the last | |
| 23 | // 1000 to 2000 stalls. | |
| 24 | const STALL_LOG_MAX_BYTES = 256 * 1024; | |
| 16 | 25 | |
| 17 | 26 | /** One sample interval as Node reports it. Delay in ns, active time in ms, CPU in µs. */ |
| 18 | 27 | export interface EventLoopReadings { |
| ... | ... | @@ -83,41 +92,75 @@ export const stallMs = ({ delayMaxNs, activeMs }: EventLoopReadings) => { |
| 83 | 92 | return delayMs; |
| 84 | 93 | }; |
| 85 | 94 | |
| 95 | const encodeStallLine = Schema.encodeUnknownEffect(Schema.fromJsonString(Schema.Unknown)); | |
| 96 | ||
| 97 | export interface StallLogOptions { | |
| 98 | readonly filePath: string; | |
| 99 | readonly maxBytes: number; | |
| 100 | } | |
| 101 | ||
| 86 | 102 | /** |
| 87 | 103 | * Samples event loop health every 30 s and records a `server.eventLoop.stall` span |
| 88 | 104 | * with a warning when the loop stalled for more than 2 s, so stalls land in |
| 89 | * the local trace file and Settings > Diagnostics without OTLP. Takes the sampler | |
| 90 | * so tests can inject readings. | |
| 105 | * the local trace file and Settings > Diagnostics without OTLP. Each stall is | |
| 106 | * also appended as one NDJSON line to a small stall log, which keeps stall | |
| 107 | * history long after the trace file has rotated. Takes the sampler and log | |
| 108 | * options so tests can inject readings and a small cap. | |
| 91 | 109 | */ |
| 92 | 110 | export const layerWith = ( |
| 93 | 111 | makeSampler: Effect.Effect<Effect.Effect<EventLoopReadings>, never, Scope.Scope>, |
| 112 | stallLog: StallLogOptions, | |
| 94 | 113 | ) => |
| 95 | 114 | Layer.effectDiscard( |
| 96 | 115 | Effect.gen(function* () { |
| 97 | 116 | const sample = yield* makeSampler; |
| 117 | // A log that cannot open must not stop the monitor; the span still records stalls. | |
| 118 | const stallSink = yield* Effect.try( | |
| 119 | () => | |
| 120 | new RotatingFileSink({ | |
| 121 | filePath: stallLog.filePath, | |
| 122 | maxBytes: stallLog.maxBytes, | |
| 123 | maxFiles: 1, | |
| 124 | throwOnError: true, | |
| 125 | }), | |
| 126 | ).pipe( | |
| 127 | Effect.catch(() => | |
| 128 | Effect.logWarning("event loop stall log unavailable", { | |
| 129 | filePath: stallLog.filePath, | |
| 130 | }).pipe(Effect.as(undefined)), | |
| 131 | ), | |
| 132 | ); | |
| 98 | 133 | const tick = Effect.gen(function* () { |
| 99 | 134 | const readings = yield* sample; |
| 100 | 135 | const delayMaxMs = stallMs(readings); |
| 101 | 136 | if (delayMaxMs === undefined) return; |
| 102 | 137 | const { utilization, usage, rssBytes } = readings; |
| 138 | const attributes = { | |
| 139 | delayMaxMs, | |
| 140 | utilization: Math.round(utilization * 100) / 100, | |
| 141 | cpuUserMs: Math.round(usage.userCPUTime / 1000), | |
| 142 | cpuSystemMs: Math.round(usage.systemCPUTime / 1000), | |
| 143 | majorPageFaults: usage.majorPageFault, | |
| 144 | minorPageFaults: usage.minorPageFault, | |
| 145 | involuntaryContextSwitches: usage.involuntaryContextSwitches, | |
| 146 | rssMb: Math.round(rssBytes / 1024 / 1024), | |
| 147 | }; | |
| 103 | 148 | // Root, as the stall has no caller to attach to. Warn level keeps it when |
| 104 | 149 | // T3CODE_TRACE_MIN_LEVEL is raised to cut trace noise. |
| 105 | 150 | yield* Effect.logWarning(`event loop stalled for ${delayMaxMs} ms`).pipe( |
| 106 | Effect.withSpan("server.eventLoop.stall", { | |
| 107 | root: true, | |
| 108 | level: "Warn", | |
| 109 | attributes: { | |
| 110 | delayMaxMs, | |
| 111 | utilization: Math.round(utilization * 100) / 100, | |
| 112 | cpuUserMs: Math.round(usage.userCPUTime / 1000), | |
| 113 | cpuSystemMs: Math.round(usage.systemCPUTime / 1000), | |
| 114 | majorPageFaults: usage.majorPageFault, | |
| 115 | minorPageFaults: usage.minorPageFault, | |
| 116 | involuntaryContextSwitches: usage.involuntaryContextSwitches, | |
| 117 | rssMb: Math.round(rssBytes / 1024 / 1024), | |
| 118 | }, | |
| 119 | }), | |
| 151 | Effect.withSpan("server.eventLoop.stall", { root: true, level: "Warn", attributes }), | |
| 120 | 152 | ); |
| 153 | if (stallSink !== undefined) { | |
| 154 | const time = DateTime.formatIso(yield* DateTime.now); | |
| 155 | yield* encodeStallLine({ time, ...attributes }).pipe( | |
| 156 | Effect.flatMap((line) => Effect.try(() => stallSink.write(`${line}\n`))), | |
| 157 | Effect.catch(() => | |
| 158 | Effect.logWarning("event loop stall log write failed", { | |
| 159 | filePath: stallLog.filePath, | |
| 160 | }), | |
| 161 | ), | |
| 162 | ); | |
| 163 | } | |
| 121 | 164 | }); |
| 122 | 165 | const wait = Effect.sleep(SAMPLE_INTERVAL); |
| 123 | 166 | // The layer builds before the rest of the server, so the first sample covers |
| ... | ... | @@ -132,4 +175,14 @@ export const layerWith = ( |
| 132 | 175 | }), |
| 133 | 176 | ); |
| 134 | 177 | |
| 135 | export const layer = layerWith(makeNodeSampler); | |
| 178 | /** Writes the stall log next to the server trace file, as `event-loop-stalls.ndjson`. */ | |
| 179 | export const layer = Layer.unwrap( | |
| 180 | Effect.gen(function* () { | |
| 181 | const { serverTracePath } = yield* ServerConfig.ServerConfig; | |
| 182 | const path = yield* Path.Path; | |
| 183 | return layerWith(makeNodeSampler, { | |
| 184 | filePath: path.join(path.dirname(serverTracePath), "event-loop-stalls.ndjson"), | |
| 185 | maxBytes: STALL_LOG_MAX_BYTES, | |
| 186 | }); | |
| 187 | }), | |
| 188 | ); |
apps/server/src/observability/Observability.ts+4| ... | ... | @@ -9,6 +9,7 @@ import * as Tracer from "effect/Tracer"; |
| 9 | 9 | import * as OtlpExporter from "effect/observability/OtlpExporter"; |
| 10 | 10 | import * as OtlpMetrics from "effect/observability/OtlpMetrics"; |
| 11 | 11 | import * as OtlpTracer from "effect/observability/OtlpTracer"; |
| 12 | import * as Statement from "effect/sql/Statement"; | |
| 12 | 13 | |
| 13 | 14 | import * as ServerConfig from "../config.ts"; |
| 14 | 15 | import * as ResourceAttribution from "../resourceTelemetry/ResourceAttribution.ts"; |
| ... | ... | @@ -30,6 +31,9 @@ export const layer = Layer.unwrap( |
| 30 | 31 | const layerTraceReferences = Layer.mergeAll( |
| 31 | 32 | Layer.succeed(Tracer.MinimumTraceLevel, config.traceMinLevel), |
| 32 | 33 | Layer.succeed(References.TracerTimingEnabled, config.traceTimingEnabled), |
| 34 | // Keeps each SQL statement's span current while it waits for a connection, | |
| 35 | // so the client can record the lock wait on it. | |
| 36 | Layer.succeed(Statement.SpanPropagationEnabled, true), | |
| 33 | 37 | HttpObservability.layer, |
| 34 | 38 | ); |
| 35 | 39 |
docs/operations/observability.md+12| ... | ... | @@ -56,6 +56,13 @@ records instead carry OTLP resource, scope, and optional status fields. |
| 56 | 56 | The `TraceRecord`, `EffectTraceRecord`, and `OtlpTraceRecord` schemas live in |
| 57 | 57 | `packages/shared/src/observability.ts`. |
| 58 | 58 | |
| 59 | SQL statement spans (named `sqlite`) and `sql.transaction` spans carry `db.connection` and | |
| 60 | `db.lock_wait_ms`. `db.connection` is `writer` for the main connection, which runs on the event loop, | |
| 61 | or `reader` for the read-only connection in a worker thread. `db.lock_wait_ms` is the part of the | |
| 62 | span spent waiting for that connection, behind other SQL. That wait does not block the event loop, | |
| 63 | so subtract it before you blame a slow span on the query. Statements inside a transaction use its | |
| 64 | connection and do not carry these attributes. | |
| 65 | ||
| 59 | 66 | DPoP proof failures include the safe `environment.dpop.failure_code` span |
| 60 | 67 | attribute. A `time_window` failure means that a signed proof was too old or too |
| 61 | 68 | far in the future for the environment server's allowed window. It can point to |
| ... | ... | @@ -95,6 +102,11 @@ the loop stalled for more than 2 s since the previous sample, it records a root |
| 95 | 102 | `T3CODE_TRACE_MIN_LEVEL` is `Warn`. The warning shows in Settings > Diagnostics unless OTLP logs are |
| 96 | 103 | on. The span time is when the sample ran, not when the stall happened. |
| 97 | 104 | |
| 105 | The trace file rotates in well under an hour on a busy server, so each stall is also appended as one | |
| 106 | NDJSON line to `event-loop-stalls.ndjson`, next to the trace file. A line has `time` and the span | |
| 107 | attributes. The file keeps the last 1000 or more stalls, with one rotated backup | |
| 108 | (`event-loop-stalls.ndjson.1`). Use it to see how often a server stalls over days. | |
| 109 | ||
| 98 | 110 | Some delay is not recorded: |
| 99 | 111 | |
| 100 | 112 | - `delayMaxMs` is the longest stall, and can undercount it by up to 1 s. The 2 s threshold applies to |
packages/shared/src/nodeSqliteClient.test.ts+95| ... | ... | @@ -10,7 +10,9 @@ import * as Layer from "effect/Layer"; |
| 10 | 10 | import * as Logger from "effect/Logger"; |
| 11 | 11 | import * as Path from "effect/Path"; |
| 12 | 12 | import * as SqlClient from "effect/sql/SqlClient"; |
| 13 | import * as Statement from "effect/sql/Statement"; | |
| 13 | 14 | import * as TestClock from "effect/testing/TestClock"; |
| 15 | import * as Tracer from "effect/Tracer"; | |
| 14 | 16 | import { vi } from "vite-plus/test"; |
| 15 | 17 | |
| 16 | 18 | import * as SqliteClient from "./nodeSqliteClient.ts"; |
| ... | ... | @@ -411,6 +413,99 @@ it.effect("keeps read-only work inside a write transaction on the writer", () => |
| 411 | 413 | ), |
| 412 | 414 | ); |
| 413 | 415 | |
| 416 | it.effect("labels SQL spans with their connection and how long they waited for its lock", () => { | |
| 417 | const spans: Array<Tracer.NativeSpan> = []; | |
| 418 | const tracer = Tracer.make({ | |
| 419 | span: (options) => { | |
| 420 | const span = new Tracer.NativeSpan(options); | |
| 421 | spans.push(span); | |
| 422 | return span; | |
| 423 | }, | |
| 424 | }); | |
| 425 | return withReaderClient((sql) => | |
| 426 | Effect.gen(function* () { | |
| 427 | const held = yield* Deferred.make<void>(); | |
| 428 | const release = yield* Deferred.make<void>(); | |
| 429 | const holder = yield* Effect.forkChild( | |
| 430 | sql.withTransaction( | |
| 431 | Deferred.succeed(held, undefined).pipe(Effect.andThen(Deferred.await(release))), | |
| 432 | ), | |
| 433 | ); | |
| 434 | yield* Deferred.await(held); | |
| 435 | // Each waiter runs until it blocks on the writer lock, before the clock moves. | |
| 436 | const statement = yield* Effect.forkChild(sql`SELECT 1`, { startImmediately: true }); | |
| 437 | const transaction = yield* Effect.forkChild(sql.withTransaction(countEntries(sql)), { | |
| 438 | startImmediately: true, | |
| 439 | }); | |
| 440 | yield* TestClock.adjust("25 millis"); | |
| 441 | yield* Deferred.succeed(release, undefined); | |
| 442 | yield* Fiber.join(holder); | |
| 443 | yield* Fiber.join(statement); | |
| 444 | yield* Fiber.join(transaction); | |
| 445 | yield* sql.withTransaction(countEntries(sql)).pipe(SqliteClient.readOnly); | |
| 446 | }), | |
| 447 | ).pipe( | |
| 448 | // The server turns this on, so a statement's span is current while it waits. | |
| 449 | Effect.provideService(Statement.SpanPropagationEnabled, true), | |
| 450 | Effect.withTracer(tracer), | |
| 451 | Effect.map(() => { | |
| 452 | // Statements inside a transaction reuse its connection, so only the | |
| 453 | // statements and transactions that took a lock are labeled. | |
| 454 | const labeled = spans | |
| 455 | .filter((span) => span.attributes.has("db.connection")) | |
| 456 | .map((span) => [ | |
| 457 | span.name, | |
| 458 | span.attributes.get("db.connection"), | |
| 459 | span.attributes.get("db.lock_wait_ms"), | |
| 460 | ]); | |
| 461 | assert.deepStrictEqual(labeled.slice(3), [ | |
| 462 | ["sql.transaction", "writer", 0], | |
| 463 | ["sqlite", "writer", 25], | |
| 464 | ["sql.transaction", "writer", 25], | |
| 465 | ["sql.transaction", "reader", 0], | |
| 466 | ]); | |
| 467 | }), | |
| 468 | ); | |
| 469 | }); | |
| 470 | ||
| 471 | it.effect("labels only the span of the statement or transaction that took the lock", () => { | |
| 472 | const spans: Array<Tracer.NativeSpan> = []; | |
| 473 | const tracer = Tracer.make({ | |
| 474 | span: (options) => { | |
| 475 | const span = new Tracer.NativeSpan(options); | |
| 476 | spans.push(span); | |
| 477 | return span; | |
| 478 | }, | |
| 479 | }); | |
| 480 | return Effect.gen(function* () { | |
| 481 | const sql = yield* SqlClient.SqlClient; | |
| 482 | const transaction = sql.withTransaction(sql`SELECT 1`); | |
| 483 | yield* transaction; | |
| 484 | // Run again nested, the same Effect reuses the outer connection and takes no lock. | |
| 485 | yield* sql.withTransaction(transaction); | |
| 486 | // With tracing off, Statement does not make its span current. | |
| 487 | yield* sql`SELECT 2`.pipe(Effect.withTracerEnabled(false)); | |
| 488 | }).pipe( | |
| 489 | Effect.withSpan("caller"), | |
| 490 | Effect.provide(SqliteClient.layer({ filename: ":memory:" })), | |
| 491 | Effect.provideService(Statement.SpanPropagationEnabled, true), | |
| 492 | Effect.withTracer(tracer), | |
| 493 | Effect.map(() => { | |
| 494 | assert.deepStrictEqual( | |
| 495 | spans | |
| 496 | .filter((span) => span.name === "caller" || span.name === "sql.transaction") | |
| 497 | .map((span) => [span.name, span.attributes.get("db.connection")]), | |
| 498 | [ | |
| 499 | ["caller", undefined], | |
| 500 | ["sql.transaction", "writer"], | |
| 501 | ["sql.transaction", "writer"], | |
| 502 | ["sql.transaction", undefined], | |
| 503 | ], | |
| 504 | ); | |
| 505 | }), | |
| 506 | ); | |
| 507 | }); | |
| 508 | ||
| 414 | 509 | it.effect("keeps large parameters off the reader worker's cached statements", () => |
| 415 | 510 | withReaderClient((sql) => |
| 416 | 511 | Effect.gen(function* () { |
packages/shared/src/nodeSqliteClient.ts+84-7| ... | ... | @@ -9,6 +9,7 @@ import * as NodeUtil from "node:util"; |
| 9 | 9 | import * as NodeWorkerThreads from "node:worker_threads"; |
| 10 | 10 | |
| 11 | 11 | import * as Cache from "effect/Cache"; |
| 12 | import * as Clock from "effect/Clock"; | |
| 12 | 13 | import * as Duration from "effect/Duration"; |
| 13 | 14 | import * as Effect from "effect/Effect"; |
| 14 | 15 | import * as Exit from "effect/Exit"; |
| ... | ... | @@ -17,11 +18,13 @@ import { identity } from "effect/Function"; |
| 17 | 18 | import * as Layer from "effect/Layer"; |
| 18 | 19 | import * as Option from "effect/Option"; |
| 19 | 20 | import * as Predicate from "effect/Predicate"; |
| 21 | import * as References from "effect/References"; | |
| 20 | 22 | import * as Schema from "effect/Schema"; |
| 21 | 23 | import * as Scope from "effect/Scope"; |
| 22 | 24 | import * as Semaphore from "effect/Semaphore"; |
| 23 | 25 | import * as Context from "effect/Context"; |
| 24 | 26 | import * as Stream from "effect/Stream"; |
| 27 | import * as Tracer from "effect/Tracer"; | |
| 25 | 28 | import * as Reactivity from "effect/reactivity/Reactivity"; |
| 26 | 29 | import * as Client from "effect/sql/SqlClient"; |
| 27 | 30 | import type { Connection } from "effect/sql/SqlConnection"; |
| ... | ... | @@ -72,6 +75,33 @@ const ReadOnly = Context.Reference<boolean>("@t3tools/shared/nodeSqliteClient/Re |
| 72 | 75 | export const readOnly = <A, E, R>(effect: Effect.Effect<A, E, R>): Effect.Effect<A, E, R> => |
| 73 | 76 | Effect.provideService(effect, ReadOnly, true); |
| 74 | 77 | |
| 78 | /** | |
| 79 | * Which connection ran the SQL, and how long it waited for that connection's | |
| 80 | * lock. The wait is time queued behind other SQL, not time the event loop was | |
| 81 | * blocked. | |
| 82 | */ | |
| 83 | interface Acquired { | |
| 84 | readonly connection: "writer" | "reader"; | |
| 85 | readonly lockWaitMs: number; | |
| 86 | } | |
| 87 | ||
| 88 | const annotateAcquired = (fiber: Fiber.Fiber<unknown, unknown>, acquired: Acquired | undefined) => { | |
| 89 | const span = Context.getOrUndefined(fiber.context, Tracer.ParentSpan); | |
| 90 | if (span?._tag !== "Span" || acquired === undefined) return; | |
| 91 | span.attribute("db.connection", acquired.connection); | |
| 92 | span.attribute("db.lock_wait_ms", acquired.lockWaitMs); | |
| 93 | }; | |
| 94 | ||
| 95 | /** | |
| 96 | * Provided by the client's `withTransaction`. Effect acquires a transaction's | |
| 97 | * connection before it makes the `sql.transaction` span current, so the acquire | |
| 98 | * leaves its result here and the transaction body puts it on the span. | |
| 99 | */ | |
| 100 | const TransactionAcquire = Context.Reference<{ acquired?: Acquired } | undefined>( | |
| 101 | "@t3tools/shared/nodeSqliteClient/TransactionAcquire", | |
| 102 | { defaultValue: () => undefined }, | |
| 103 | ); | |
| 104 | ||
| 75 | 105 | export class UnsupportedNodeSqliteVersionError extends Schema.TaggedError<UnsupportedNodeSqliteVersionError>()( |
| 76 | 106 | "UnsupportedNodeSqliteVersionError", |
| 77 | 107 | { |
| ... | ... | @@ -785,7 +815,7 @@ const make = Effect.fn("makeWithDatabase")(function* ( |
| 785 | 815 | options.readerWorker && isFileDatabase ? yield* makeReader(options) : undefined; |
| 786 | 816 | const readerSemaphore = yield* Semaphore.make(1); |
| 787 | 817 | |
| 788 | const writer = { lock: semaphore, connection }; | |
| 818 | const writer = { name: "writer" as const, lock: semaphore, connection }; | |
| 789 | 819 | // Picks the reader only for `readOnly` work, and the writer whenever the |
| 790 | 820 | // reader is turned off. |
| 791 | 821 | const route = Effect.withFiber((fiber) => |
| ... | ... | @@ -793,28 +823,59 @@ const make = Effect.fn("makeWithDatabase")(function* ( |
| 793 | 823 | ? Effect.map(acquireReader, (readerConnection) => |
| 794 | 824 | readerConnection === undefined |
| 795 | 825 | ? writer |
| 796 | : { lock: readerSemaphore, connection: readerConnection }, | |
| 826 | : { name: "reader" as const, lock: readerSemaphore, connection: readerConnection }, | |
| 797 | 827 | ) |
| 798 | 828 | : Effect.succeed(writer), |
| 799 | 829 | ); |
| 800 | 830 | |
| 831 | const acquired = ( | |
| 832 | target: { readonly name: Acquired["connection"] }, | |
| 833 | clock: Clock.Clock, | |
| 834 | start: bigint, | |
| 835 | ): Acquired => ({ | |
| 836 | connection: target.name, | |
| 837 | lockWaitMs: Number((clock.monotonicTimeNanosUnsafe() - start) / 1000n) / 1000, | |
| 838 | }); | |
| 839 | ||
| 801 | 840 | const acquirer = Effect.flatMap(route, (target) => |
| 802 | target.lock.withPermits(1)(Effect.succeed(target.connection)), | |
| 841 | Effect.withFiber((fiber) => { | |
| 842 | // The statement's span is current here only when it propagates, which | |
| 843 | // Statement skips while tracing is off. Otherwise the current span is | |
| 844 | // the caller's, so leave it alone. | |
| 845 | if ( | |
| 846 | !fiber.getRef(References.TracerEnabled) || | |
| 847 | !fiber.getRef(Statement.SpanPropagationEnabled) | |
| 848 | ) { | |
| 849 | return target.lock.withPermits(1)(Effect.succeed(target.connection)); | |
| 850 | } | |
| 851 | const clock = fiber.getRef(Clock.Clock); | |
| 852 | const start = clock.monotonicTimeNanosUnsafe(); | |
| 853 | return target.lock.withPermits(1)( | |
| 854 | Effect.sync(() => { | |
| 855 | annotateAcquired(fiber, acquired(target, clock, start)); | |
| 856 | return target.connection; | |
| 857 | }), | |
| 858 | ); | |
| 859 | }), | |
| 803 | 860 | ); |
| 804 | 861 | const transactionAcquirer = Effect.flatMap(route, (target) => |
| 805 | 862 | Effect.uninterruptibleMask((restore) => { |
| 806 | 863 | const fiber = Fiber.getCurrent()!; |
| 807 | 864 | const scope = Context.getUnsafe(fiber.context, Scope.Scope); |
| 865 | const clock = fiber.getRef(Clock.Clock); | |
| 866 | const start = clock.monotonicTimeNanosUnsafe(); | |
| 808 | 867 | return Effect.as( |
| 809 | Effect.tap(restore(target.lock.take(1)), () => | |
| 810 | Scope.addFinalizer(scope, target.lock.release(1)), | |
| 811 | ), | |
| 868 | Effect.tap(restore(target.lock.take(1)), () => { | |
| 869 | const pending = fiber.getRef(TransactionAcquire); | |
| 870 | if (pending !== undefined) pending.acquired = acquired(target, clock, start); | |
| 871 | return Scope.addFinalizer(scope, target.lock.release(1)); | |
| 872 | }), | |
| 812 | 873 | target.connection, |
| 813 | 874 | ); |
| 814 | 875 | }), |
| 815 | 876 | ); |
| 816 | 877 | |
| 817 | return yield* Client.make({ | |
| 878 | const client = yield* Client.make({ | |
| 818 | 879 | acquirer, |
| 819 | 880 | compiler, |
| 820 | 881 | transactionAcquirer, |
| ... | ... | @@ -831,6 +892,22 @@ const make = Effect.fn("makeWithDatabase")(function* ( |
| 831 | 892 | ], |
| 832 | 893 | transformRows, |
| 833 | 894 | }); |
| 895 | const withTransaction = client.withTransaction; | |
| 896 | return Object.assign(client, { | |
| 897 | // Each run gets its own holder, so a reused transaction Effect never | |
| 898 | // carries an earlier run's attributes. | |
| 899 | withTransaction: <A, E, R>(effect: Effect.Effect<A, E, R>) => | |
| 900 | Effect.suspend(() => { | |
| 901 | const pending: { acquired?: Acquired } = {}; | |
| 902 | // The body runs with the `sql.transaction` span current. A nested | |
| 903 | // transaction acquires nothing, so its span gets no attributes. | |
| 904 | const body = Effect.withFiber<A, E, R>((fiber) => { | |
| 905 | annotateAcquired(fiber, pending.acquired); | |
| 906 | return effect; | |
| 907 | }); | |
| 908 | return withTransaction(body).pipe(Effect.provideService(TransactionAcquire, pending)); | |
| 909 | }), | |
| 910 | }); | |
| 834 | 911 | }); |
| 835 | 912 | |
| 836 | 913 | export const layer = (config: SqliteClientConfig): Layer.Layer<Client.SqlClient, SqlError> => |