test(performance): preserve delayed worker samples (#1305)

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();
 

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<boolean> {
     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<void>((resolvePromise) => {

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,

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
             ) {

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(

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