mirror of
https://github.com/4gray/iptvnator.git
synced 2026-10-08 17:06:15 -08:00
test(performance): deflake the real-timer event-loop delay spec (#1293)
* test(performance): deflake the real-timer event-loop delay spec The real-timer capture spec failed under full-suite parallelism because `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 inside its fixed 50ms wall-clock budget, and a machine running 10 Jest workers stretches a single turn past 20ms. The capture then degraded to a documented `event-loop-delay-arm-timeout`, which is the intended graceful path, while the spec asserted the happy path of that race and turned an environmental outcome into a red build. Retry the real-runtime capture within a 5s budget instead. The real `node:perf_hooks` runtime and the real 20ms block are kept, since the fake harness returns a hard-coded histogram max and never measures anything. Every attempt still asserts a contract: instrumentation never breaks the wrapped work, and a null delay must carry a documented arm/flush timeout rather than being silently null. Budget exhaustion warns instead of failing, so load can no longer produce a false failure. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> * test(performance): assert the real delay measurement unconditionally Codex flagged that budget exhaustion still passed the test, so a regression that made arming or flushing time out on every attempt would have been reported as a warning rather than a failure - removing the only assertion backed by Node's real histogram and a genuine event-loop block. Drop the tolerant retry loop. The arming deadline is read through the injectable `readMonotonicMs()`, so scaling only that clock leaves the wait bounded by its other limit, the 50-poll ceiling, which is ~25x the two event-loop 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, since its only other consumer records phase events and this spec records none. The test now always asserts a real measurement and hard-fails otherwise. Verified by mutation: forcing arming to never arm fails it, and dropping the deliberate block fails it at maxMs 3.8ms against the 10ms floor. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> --------- Co-authored-by: Claude Opus 5 <noreply@anthropic.com>
This commit is contained in:
1 parent
518964c57f
commit
d2fd27b535
1 file changed
+69
-19
+69
-19
@@ -6,11 +6,43 @@ 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';
|
||||
|
||||
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];
|
||||
|
||||
@@ -70,26 +102,44 @@ describe('worker performance capture concurrency and real timers', () => {
|
||||
expect(activeCaptures.size).toBe(0);
|
||||
});
|
||||
|
||||
it('reliably observes a real 20ms event-loop block after condition-based arming', async () => {
|
||||
process.env[PROFILING_ENV] = '1';
|
||||
it(
|
||||
'measures a real 20ms event-loop block through condition-based arming',
|
||||
async () => {
|
||||
process.env[PROFILING_ENV] = '1';
|
||||
|
||||
const capture = startWorkerPerformanceCapture();
|
||||
await armWorkerPerformanceCapture(capture);
|
||||
const execution = await executeWithWorkerPerformanceCapture(
|
||||
capture,
|
||||
async () => {
|
||||
const blockStartedAt = performance.now();
|
||||
while (performance.now() - blockStartedAt < 20) {
|
||||
// This deliberate block is the behavior under measurement.
|
||||
// No `enabled` override: the env variable is the opt-in under test.
|
||||
const capture = startWorkerPerformanceCapture({
|
||||
runtime: createRuntimeWithScaledWaitDeadline(),
|
||||
});
|
||||
|
||||
expect(capture).not.toBeNull();
|
||||
|
||||
await armWorkerPerformanceCapture(capture);
|
||||
const execution = await executeWithWorkerPerformanceCapture(
|
||||
capture,
|
||||
async () => {
|
||||
const blockStartedAt = performance.now();
|
||||
while (
|
||||
performance.now() - blockStartedAt <
|
||||
BLOCK_DURATION_MS
|
||||
) {
|
||||
// This deliberate block is the behavior under measurement.
|
||||
}
|
||||
}
|
||||
}
|
||||
);
|
||||
);
|
||||
|
||||
expect(execution.success).toBe(true);
|
||||
expect(execution.performance?.eventLoopDelay).not.toBeNull();
|
||||
expect(execution.performance?.eventLoopDelay?.maxMs).toBeGreaterThan(
|
||||
10
|
||||
);
|
||||
expect(execution.performance?.histogramFlushedEpochMs).not.toBeNull();
|
||||
});
|
||||
expect(execution.success).toBe(true);
|
||||
expect(execution.performance?.invalidReason).toBeNull();
|
||||
expect(
|
||||
execution.performance?.eventLoopDelayUnavailableReason
|
||||
).toBeNull();
|
||||
expect(
|
||||
execution.performance?.histogramFlushedEpochMs
|
||||
).not.toBeNull();
|
||||
expect(
|
||||
execution.performance?.eventLoopDelay?.maxMs
|
||||
).toBeGreaterThan(10);
|
||||
},
|
||||
REAL_TIMER_TEST_TIMEOUT_MS
|
||||
);
|
||||
});
|
||||
Reference in new issue
Block a user