diff --git a/apps/electron-backend/src/app/workers/worker-performance-capture.concurrency.spec.ts b/apps/electron-backend/src/app/workers/worker-performance-capture.concurrency.spec.ts index 263f43f64..ab21a14cd 100644 --- a/apps/electron-backend/src/app/workers/worker-performance-capture.concurrency.spec.ts +++ b/apps/electron-backend/src/app/workers/worker-performance-capture.concurrency.spec.ts @@ -6,9 +6,7 @@ import { releaseDatabaseWorkerPerformanceCapture, startWorkerPerformanceCapture, type WorkerPerformanceCapture, - type WorkerPerformanceCaptureRuntime, } from './worker-performance-capture'; -import { DEFAULT_WORKER_PERFORMANCE_RUNTIME } from './worker-performance-capture.runtime'; import { createFakeRuntime } from './worker-performance-capture.test-harness'; const PROFILING_ENV = 'IPTVNATOR_PERF_WORKER_PROFILING'; @@ -16,33 +14,6 @@ const PROFILING_ENV = 'IPTVNATOR_PERF_WORKER_PROFILING'; const BLOCK_DURATION_MS = 20; const REAL_TIMER_TEST_TIMEOUT_MS = 30_000; -/** - * `monitorEventLoopDelay()` records nothing on its first internal timer tick — - * that tick only seeds the previous timestamp, so the first delay sample lands - * on the second tick. Condition-based arming therefore needs two event-loop - * turns, and it budgets for them with a 50ms deadline read from - * `readMonotonicMs()`. A machine running the full Jest suite in parallel can - * stretch a single turn past 20ms, so that deadline expires against the - * scheduler rather than against any defect in the capture code. - * - * Slowing only that deadline clock leaves the wait bounded by its other limit, - * the 50-poll ceiling, which is ~25x the two turns arming actually needs. - * Everything else stays production code: the real `monitorEventLoopDelay()` - * histogram, real `setTimeout()` polling, and real epoch/CPU/ELU boundaries. - * The scaled clock reaches nothing but the wait budgets — its only other - * consumer records phase events, and this spec records none. - */ -const WAIT_DEADLINE_CLOCK_SCALE = 50; - -function createRuntimeWithScaledWaitDeadline(): WorkerPerformanceCaptureRuntime { - return { - ...DEFAULT_WORKER_PERFORMANCE_RUNTIME, - readMonotonicMs: () => - DEFAULT_WORKER_PERFORMANCE_RUNTIME.readMonotonicMs() / - WAIT_DEADLINE_CLOCK_SCALE, - }; -} - describe('worker performance capture concurrency and real timers', () => { const originalProfilingValue = process.env[PROFILING_ENV]; @@ -108,9 +79,7 @@ describe('worker performance capture concurrency and real timers', () => { process.env[PROFILING_ENV] = '1'; // No `enabled` override: the env variable is the opt-in under test. - const capture = startWorkerPerformanceCapture({ - runtime: createRuntimeWithScaledWaitDeadline(), - }); + const capture = startWorkerPerformanceCapture(); expect(capture).not.toBeNull(); diff --git a/apps/electron-backend/src/app/workers/worker-performance-capture.histogram.ts b/apps/electron-backend/src/app/workers/worker-performance-capture.histogram.ts index a4951d6cc..ffad6be72 100644 --- a/apps/electron-backend/src/app/workers/worker-performance-capture.histogram.ts +++ b/apps/electron-backend/src/app/workers/worker-performance-capture.histogram.ts @@ -37,7 +37,10 @@ export function markEventLoopDelayUnavailable( export async function waitForHistogramCondition( capture: WorkerPerformanceCapture, - condition: (histogram: WorkerEventLoopDelayHistogram) => boolean + condition: (histogram: WorkerEventLoopDelayHistogram) => boolean, + options: { + readonly minimumPollsBeforeElapsedDeadline?: number; + } = {} ): Promise { const histogram = capture.eventLoopDelay; if ( @@ -58,6 +61,8 @@ export async function waitForHistogramCondition( const maximumPolls = Math.ceil( HISTOGRAM_WAIT_CAP_MS / HISTOGRAM_POLL_INTERVAL_MS ); + const minimumPollsBeforeElapsedDeadline = + options.minimumPollsBeforeElapsedDeadline ?? 0; let pollCount = 0; while (true) { @@ -80,16 +85,20 @@ export async function waitForHistogramCondition( } if ( !Number.isFinite(elapsedMs) || - elapsedMs >= HISTOGRAM_WAIT_CAP_MS || - pollCount >= maximumPolls + pollCount >= maximumPolls || + (pollCount >= minimumPollsBeforeElapsedDeadline && + elapsedMs >= HISTOGRAM_WAIT_CAP_MS) ) { return false; } - const delayMs = Math.min( - HISTOGRAM_POLL_INTERVAL_MS, - HISTOGRAM_WAIT_CAP_MS - Math.max(0, elapsedMs) - ); + const delayMs = + elapsedMs >= HISTOGRAM_WAIT_CAP_MS + ? HISTOGRAM_POLL_INTERVAL_MS + : Math.min( + HISTOGRAM_POLL_INTERVAL_MS, + HISTOGRAM_WAIT_CAP_MS - Math.max(0, elapsedMs) + ); try { pollCount += 1; await new Promise((resolvePromise) => { diff --git a/apps/electron-backend/src/app/workers/worker-performance-capture.resilience.spec.ts b/apps/electron-backend/src/app/workers/worker-performance-capture.resilience.spec.ts index c56a2fb36..806200729 100644 --- a/apps/electron-backend/src/app/workers/worker-performance-capture.resilience.spec.ts +++ b/apps/electron-backend/src/app/workers/worker-performance-capture.resilience.spec.ts @@ -56,6 +56,63 @@ describe('worker performance capture resilience', () => { }); }); + it('allows the second required histogram turn after a delayed first turn', async () => { + const harness = createFakeRuntime({ + armHistogramAfterTimeoutCount: 2, + timeoutElapsedMs: [86.202, 1, 1], + }); + const capture = startWorkerPerformanceCapture({ + enabled: true, + runtime: harness.runtime, + }); + + await armWorkerPerformanceCapture(capture); + const execution = await executeWithWorkerPerformanceCapture( + capture, + async () => 'result' + ); + + expect(harness.scheduledTimeouts.slice(0, 2)).toEqual([1, 1]); + expect(execution.performance).toMatchObject({ + eventLoopDelay: { + maxMs: 24, + p95Ms: 18, + p99Ms: 22, + }, + eventLoopDelayUnavailableReason: null, + histogramFlushedEpochMs: 145, + invalidReason: null, + }); + }); + + it('times out after the second required turn when delayed arming never samples', async () => { + const harness = createFakeRuntime({ + armHistogram: false, + timeoutElapsedMs: [86.202, 1], + }); + const capture = startWorkerPerformanceCapture({ + enabled: true, + runtime: harness.runtime, + }); + + await armWorkerPerformanceCapture(capture); + const execution = await executeWithWorkerPerformanceCapture( + capture, + async () => 'result' + ); + + expect(harness.scheduledTimeouts).toEqual([1, 1]); + expect(execution).toMatchObject({ + result: 'result', + success: true, + performance: { + eventLoopDelay: null, + eventLoopDelayUnavailableReason: + WORKER_PERFORMANCE_UNAVAILABLE_REASON.EVENT_LOOP_DELAY_ARM_TIMEOUT, + }, + }); + }); + it('cannot poll forever when the monotonic runtime clock stalls', async () => { const harness = createFakeRuntime({ armHistogram: false, diff --git a/apps/electron-backend/src/app/workers/worker-performance-capture.test-harness.ts b/apps/electron-backend/src/app/workers/worker-performance-capture.test-harness.ts index 54517e637..aa5fb6f6d 100644 --- a/apps/electron-backend/src/app/workers/worker-performance-capture.test-harness.ts +++ b/apps/electron-backend/src/app/workers/worker-performance-capture.test-harness.ts @@ -4,11 +4,13 @@ import type { } from './worker-performance-capture'; interface FakeRuntimeOptions { + armHistogramAfterTimeoutCount?: number; armHistogram?: boolean; flushHistogram?: boolean; histogramDisableResult?: boolean; stallMonotonicClock?: boolean; threadCpuAvailable?: boolean; + timeoutElapsedMs?: readonly number[]; throwBoundaryCallbacks?: boolean; throwHistogramDisable?: boolean; throwHistogramCountAtRead?: number; @@ -130,15 +132,21 @@ export function createFakeRuntime( throw new Error('timer callback unavailable'); } if (options.stallMonotonicClock !== true) { - monotonicMs += delayMs; + monotonicMs += + options.timeoutElapsedMs?.[timeoutCount] ?? delayMs; } else if (timeoutCount >= 55) { throw new Error('test scheduler fail-safe'); } timeoutCount += 1; - if (timeoutCount === 1 && options.armHistogram !== false) { + const armAfterTimeoutCount = + options.armHistogramAfterTimeoutCount ?? 1; + if ( + timeoutCount === armAfterTimeoutCount && + options.armHistogram !== false + ) { histogramCount += 1; } else if ( - timeoutCount > 1 && + timeoutCount > armAfterTimeoutCount && options.armHistogram !== false && options.flushHistogram !== false ) { diff --git a/apps/electron-backend/src/app/workers/worker-performance-capture.ts b/apps/electron-backend/src/app/workers/worker-performance-capture.ts index 3fa1a8baa..2f5cdb15a 100644 --- a/apps/electron-backend/src/app/workers/worker-performance-capture.ts +++ b/apps/electron-backend/src/app/workers/worker-performance-capture.ts @@ -103,7 +103,11 @@ export async function armWorkerPerformanceCapture( } const armed = await waitForHistogramCondition( capture, - (histogram) => histogram.count > 0 + (histogram) => histogram.count > 0, + { + // The histogram needs two turns before its first sample. + minimumPollsBeforeElapsedDeadline: 2, + } ); if (!armed && capture.invalidReason === null) { markEventLoopDelayUnavailable( diff --git a/docs/architecture/sqlite-db-worker.md b/docs/architecture/sqlite-db-worker.md index f8006d8e6..1ed1dc64f 100644 --- a/docs/architecture/sqlite-db-worker.md +++ b/docs/architecture/sqlite-db-worker.md @@ -137,11 +137,13 @@ Each enabled request gets a fresh event-loop-delay histogram and records: Histogram arming waits until the histogram has a sample; flushing waits for its sample count to advance after work ends. Both waits use condition-based timer -polling. Each wait stops after 50 ms of observed monotonic time or its bounded -poll count; arming and flushing have separate caps, and timer scheduling may -overshoot wall-clock time. A timeout or profiling API failure never replaces -the business response: timestamps and any independently available CPU/ELU -metrics remain valid, while event-loop delay is `null` with a fixed reason. +polling. Arming permits the two poll turns that `monitorEventLoopDelay()` needs +before its first sample, then applies the 50 ms elapsed deadline; it always +stops by the 50-poll ceiling. Flushing has no poll floor and stops after 50 ms +or 50 polls. The waits have separate caps, and timer scheduling may overshoot +wall-clock time. A timeout or profiling API failure never replaces the business +response: timestamps and any independently available CPU/ELU metrics remain +valid, while event-loop delay is `null` with a fixed reason. The long-lived database worker still executes concurrent requests without a profiling queue. If captures overlap, every overlapping response carries