mirror of
https://github.com/QwenLM/qwen-code.git
synced 2026-08-11 01:36:35 +00:00
* feat(telemetry): add runtime memory/CPU sampling with OTel metric reporting Add a lightweight RuntimeSampleRing to the memory pressure monitor that captures memory (RSS, heap, external) and CPU (user/system/percent) on every pressure check. The ring buffer always records (for local crash diagnostics), while OTel metric reporting is gated behind isPerformanceMonitoringActive() — zero overhead when telemetry is off. When the monitor triggers a diagnostics dump (hard/critical pressure), the recent samples are included in the dump JSON as recentSamples[], giving maintainers a memory/CPU trend leading up to the event. Closes #4183 * fix(telemetry): address code review feedback on runtime sampling - Fix Critical: record() no longer calls process.memoryUsage() redundantly; reuses the snapshot from getPressureLevelWithMem() - Fix JSDoc: class comment now correctly states ring buffer is always active - Fix elapsed=0: return a shallow copy (not internal reference) to prevent caller mutation of ring buffer state - Fix cpuPercent: normalize by os.cpus().length so values stay 0-100% - Remove dead fields: cpuUserMs/cpuSystemMs had no downstream consumer - Export RuntimeSampleRing class for direct unit testing - Add runtimeSampleRing.test.ts with coverage for: normal record, elapsed=0 edge case, ring eviction, getAll copy semantics, and reset - Add dumper test verifying recentSamples appears in serialized output * fix(telemetry): restore getPressureLevel spy contract and add os.cpus mock - performCheckInternal now calls the public getPressureLevel() (which tests spy on) instead of a private getPressureLevelWithMem(), restoring the test spy contract for 4 cleanup tests - Remove unused getPressureLevelWithMem() — the mem snapshot for record() is fetched directly via process.memoryUsage() in the sampling try-catch block - Add cpus() to the node:os mock in memoryPressureMonitor.test.ts to satisfy the new CPU_CORE_COUNT module-level constant * fix(telemetry): address review round 3 — single memoryUsage snapshot and test coverage - performCheckInternal now reads process.memoryUsage() once per check cycle and shares the snapshot between getPressureLevel() and runtimeSamples.record(), removing the redundant syscall while keeping the public getPressureLevel() spy contract (it still gets called, with an optional pre-fetched snapshot) - fix cpuPercent JSDoc: the value is a percentage of total system capacity (normalized by core count), not per-core - add test: OTel reporting path (recordMemoryUsage ×2 + recordCpuUsage ×1 when isPerformanceMonitoringActive is true, nothing when false) via a partial mock of telemetry/metrics.js - add test: diagnostics dumper receives non-empty runtime samples on hard pressure - add test: CPU delta from a same-tick (elapsed <= 0) sample accumulates into the next sample instead of being lost - adjust queued-cleanup-failure test mock sequence for the per-check sampling snapshot introduced by this branch * fix(telemetry): resolve os.cpus() import-time crash and harden CPU sampling Move the CPU core count off the module-level `os.cpus()` constant into a lazy, memoized getCpuCoreCount(). Evaluating os.cpus() at import time broke every test suite that vi.mock('node:os') without a cpus export, since this module is transitively imported by config.ts — turning CI red on all three platforms. While there, harden RuntimeSampleRing.record(): - prefer os.availableParallelism() (honors cgroup quotas) over os.cpus().length - clamp cpuPercent to >= 0 for non-monotonic process.cpuUsage() in containers/VMs - on a same-ms tick, capture the fresh memory snapshot (only cpuPercent stays stale) and still push the sample so the ring is never empty on the first call Add tests covering fresh-memory-on-same-tick and first-call-same-ms recording. * fix(telemetry): avoid duplicate failing memoryUsage syscall on read failure When process.memoryUsage() throws, readMemoryUsage() already logs and returns undefined. Passing that undefined into getPressureLevel() made it call readMemoryUsage() again via its memSnapshot fallback, firing a second failing syscall and logging the same error twice per check cycle. Guard the call with `mem ? getPressureLevel(mem) : 'normal'`. Add a performCheck()-level test asserting it does not throw, skips OTel reporting, and logs the read failure exactly once. * fix(telemetry): harden CPU sampling, clamp burst, demote repeat log, reuse ring in dumper Address 4 review findings from CI pipeline review: 1. Critical — wrap process.cpuUsage() in safeCpuUsage() try/catch so restricted containers that lack /proc/self/stat don't crash the entire memory-pressure system (constructor, record, reset). 2. Clamp cpuPercent to Math.min(100, ...) to handle cgroup CPU bursting where reported CPU-time transiently exceeds wall-clock × core count. 3. Add hasLoggedSamplingError flag: first sampling failure logs at error level (operators see "metrics enabled but broken"), subsequent failures demote to debug (avoids log spam). 4. Phase 1 of memoryDiagnosticsDumper reuses the last ring sample for memoryUsage instead of a redundant process.memoryUsage() syscall that could throw under extreme memory pressure. All 4 behaviors have dedicated test coverage (5 new tests, 90 total).
283 lines
8.1 KiB
TypeScript
283 lines
8.1 KiB
TypeScript
/**
|
||
* @license
|
||
* Copyright 2026 Qwen Team
|
||
* SPDX-License-Identifier: Apache-2.0
|
||
*/
|
||
|
||
import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest';
|
||
import * as os from 'node:os';
|
||
import { RuntimeSampleRing } from './memoryPressureMonitor.js';
|
||
|
||
describe('RuntimeSampleRing', () => {
|
||
let ring: RuntimeSampleRing;
|
||
|
||
beforeEach(() => {
|
||
ring = new RuntimeSampleRing();
|
||
});
|
||
|
||
afterEach(() => {
|
||
vi.restoreAllMocks();
|
||
});
|
||
|
||
it('records a sample with correct memory fields', () => {
|
||
const mem = {
|
||
rss: 500_000_000,
|
||
heapUsed: 300_000_000,
|
||
heapTotal: 400_000_000,
|
||
external: 10_000_000,
|
||
arrayBuffers: 5_000_000,
|
||
};
|
||
|
||
const sample = ring.record(mem);
|
||
|
||
expect(sample.rss).toBe(500_000_000);
|
||
expect(sample.heapUsed).toBe(300_000_000);
|
||
expect(sample.heapTotal).toBe(400_000_000);
|
||
expect(sample.external).toBe(10_000_000);
|
||
expect(sample.ts).toBeGreaterThan(0);
|
||
expect(typeof sample.cpuPercent).toBe('number');
|
||
});
|
||
|
||
it('computes cpuPercent as a normalized percentage', () => {
|
||
const mem = {
|
||
rss: 100,
|
||
heapUsed: 50,
|
||
heapTotal: 80,
|
||
external: 10,
|
||
arrayBuffers: 0,
|
||
};
|
||
|
||
// First call establishes baseline
|
||
ring.record(mem);
|
||
|
||
// Wait a bit to get nonzero elapsed
|
||
vi.spyOn(Date, 'now').mockReturnValue(Date.now() + 100);
|
||
const sample = ring.record(mem);
|
||
|
||
// cpuPercent should be a finite number (exact value depends on real CPU work)
|
||
expect(Number.isFinite(sample.cpuPercent)).toBe(true);
|
||
expect(sample.cpuPercent).toBeGreaterThanOrEqual(0);
|
||
});
|
||
|
||
it('reuses the previous cpuPercent but captures fresh memory on a same-ms tick', () => {
|
||
const mem = {
|
||
rss: 100,
|
||
heapUsed: 50,
|
||
heapTotal: 80,
|
||
external: 10,
|
||
arrayBuffers: 0,
|
||
};
|
||
|
||
const fixedNow = Date.now();
|
||
vi.spyOn(Date, 'now').mockReturnValue(fixedNow);
|
||
|
||
const first = ring.record(mem);
|
||
|
||
// Same timestamp, but memory has moved. cpuPercent can't be recomputed with
|
||
// zero elapsed time, so it stays at the previous value — but the memory
|
||
// fields must reflect the fresh snapshot, since the caller reports them.
|
||
const grownMem = { ...mem, rss: 999, heapUsed: 777 };
|
||
const second = ring.record(grownMem);
|
||
|
||
expect(second.cpuPercent).toBe(first.cpuPercent);
|
||
expect(second.rss).toBe(999);
|
||
expect(second.heapUsed).toBe(777);
|
||
expect(second).not.toBe(first);
|
||
});
|
||
|
||
it('records a sample even when the very first call lands on the same ms', () => {
|
||
const mem = {
|
||
rss: 123,
|
||
heapUsed: 50,
|
||
heapTotal: 80,
|
||
external: 10,
|
||
arrayBuffers: 0,
|
||
};
|
||
|
||
// Pin time to the ring's construction instant so the first record() hits the
|
||
// elapsed <= 0 branch with an empty buffer. The sample must still be stored,
|
||
// otherwise the first hard/critical dump would miss it.
|
||
const fixedNow = Date.now();
|
||
vi.spyOn(Date, 'now').mockReturnValue(fixedNow);
|
||
const localRing = new RuntimeSampleRing();
|
||
|
||
const sample = localRing.record(mem);
|
||
|
||
expect(sample.cpuPercent).toBe(0);
|
||
expect(sample.rss).toBe(123);
|
||
expect(localRing.getAll()).toHaveLength(1);
|
||
});
|
||
|
||
it('accumulates the CPU delta from a same-tick sample into the next sample', () => {
|
||
const mem = {
|
||
rss: 100,
|
||
heapUsed: 50,
|
||
heapTotal: 80,
|
||
external: 10,
|
||
arrayBuffers: 0,
|
||
};
|
||
|
||
let mockCpu = { user: 0, system: 0 };
|
||
vi.spyOn(process, 'cpuUsage').mockImplementation(() => ({ ...mockCpu }));
|
||
let mockTime = 1000;
|
||
vi.spyOn(Date, 'now').mockImplementation(() => mockTime);
|
||
|
||
// Construct under mocked time so the baseline is deterministic:
|
||
// prevCpuUsage = {0, 0}, prevSampleTime = 1000.
|
||
const localRing = new RuntimeSampleRing();
|
||
|
||
mockTime = 1100;
|
||
mockCpu = { user: 4000, system: 4000 }; // 8ms CPU over 100ms
|
||
const first = localRing.record(mem);
|
||
|
||
// Same ms tick (elapsed = 0): the 8ms of CPU accrued since `first`
|
||
// must NOT be consumed — prevCpuUsage/prevSampleTime stay untouched.
|
||
mockCpu = { user: 8000, system: 8000 };
|
||
const second = localRing.record(mem);
|
||
expect(second).toEqual(first);
|
||
|
||
mockTime = 1200;
|
||
mockCpu = { user: 12000, system: 12000 };
|
||
const third = localRing.record(mem);
|
||
|
||
// 16ms of CPU (8ms from the skipped tick + 8ms after) over 100ms = 16%,
|
||
// normalized by core count. A regression that updates prevCpuUsage in the
|
||
// elapsed <= 0 branch would yield only 8% / cores here.
|
||
// Mirror getCpuCoreCount()'s resolution order so the assertion holds
|
||
// regardless of which API the implementation reads.
|
||
const coreCount = os.availableParallelism?.() ?? os.cpus().length ?? 1;
|
||
expect(third.cpuPercent).toBeCloseTo(16 / coreCount, 2);
|
||
});
|
||
|
||
it('evicts oldest sample when exceeding buffer size', () => {
|
||
const mem = {
|
||
rss: 100,
|
||
heapUsed: 50,
|
||
heapTotal: 80,
|
||
external: 10,
|
||
arrayBuffers: 0,
|
||
};
|
||
|
||
// Mock time must start AFTER the ring's construction time to ensure elapsed > 0.
|
||
let mockTime = Date.now() + 1000;
|
||
vi.spyOn(Date, 'now').mockImplementation(() => {
|
||
mockTime += 1000;
|
||
return mockTime;
|
||
});
|
||
|
||
for (let i = 0; i < 65; i++) {
|
||
ring.record(mem);
|
||
}
|
||
|
||
const all = ring.getAll();
|
||
expect(all.length).toBe(60);
|
||
});
|
||
|
||
it('getAll returns a copy that does not affect internal state', () => {
|
||
const mem = {
|
||
rss: 100,
|
||
heapUsed: 50,
|
||
heapTotal: 80,
|
||
external: 10,
|
||
arrayBuffers: 0,
|
||
};
|
||
|
||
let mockTime = Date.now() + 1000;
|
||
vi.spyOn(Date, 'now').mockImplementation(() => {
|
||
mockTime += 1000;
|
||
return mockTime;
|
||
});
|
||
|
||
ring.record(mem);
|
||
ring.record(mem);
|
||
|
||
const snapshot = ring.getAll();
|
||
expect(snapshot.length).toBe(2);
|
||
|
||
snapshot.length = 0;
|
||
expect(ring.getAll().length).toBe(2);
|
||
});
|
||
|
||
it('reset clears all samples', () => {
|
||
const mem = {
|
||
rss: 100,
|
||
heapUsed: 50,
|
||
heapTotal: 80,
|
||
external: 10,
|
||
arrayBuffers: 0,
|
||
};
|
||
|
||
let mockTime = Date.now() + 1000;
|
||
vi.spyOn(Date, 'now').mockImplementation(() => {
|
||
mockTime += 1000;
|
||
return mockTime;
|
||
});
|
||
|
||
ring.record(mem);
|
||
ring.record(mem);
|
||
expect(ring.getAll().length).toBe(2);
|
||
|
||
ring.reset();
|
||
expect(ring.getAll().length).toBe(0);
|
||
});
|
||
|
||
it('survives process.cpuUsage() throwing during construction and record()', () => {
|
||
vi.spyOn(process, 'cpuUsage').mockImplementation(() => {
|
||
throw new Error('/proc/self/stat unavailable');
|
||
});
|
||
|
||
// Constructor calls safeCpuUsage() for the initial baseline — must not throw.
|
||
const restrictedRing = new RuntimeSampleRing();
|
||
|
||
let mockTime = Date.now() + 100;
|
||
vi.spyOn(Date, 'now').mockImplementation(() => {
|
||
mockTime += 100;
|
||
return mockTime;
|
||
});
|
||
|
||
const mem = {
|
||
rss: 500_000_000,
|
||
heapUsed: 300_000_000,
|
||
heapTotal: 400_000_000,
|
||
external: 10_000_000,
|
||
arrayBuffers: 5_000_000,
|
||
};
|
||
|
||
// record() also calls safeCpuUsage() — must not throw.
|
||
const sample = restrictedRing.record(mem);
|
||
expect(sample.rss).toBe(500_000_000);
|
||
expect(sample.cpuPercent).toBe(0);
|
||
|
||
// reset() calls safeCpuUsage() for the new baseline — must not throw.
|
||
expect(() => restrictedRing.reset()).not.toThrow();
|
||
});
|
||
|
||
it('clamps cpuPercent at 100 when CPU bursting exceeds wall-clock × cores', () => {
|
||
const coreCount = os.availableParallelism?.() ?? os.cpus().length ?? 1;
|
||
|
||
let mockCpu = { user: 0, system: 0 };
|
||
vi.spyOn(process, 'cpuUsage').mockImplementation(() => ({ ...mockCpu }));
|
||
let mockTime = 1000;
|
||
vi.spyOn(Date, 'now').mockImplementation(() => mockTime);
|
||
|
||
const localRing = new RuntimeSampleRing();
|
||
|
||
// Advance 100ms but report enough CPU-time to exceed 100% per core.
|
||
// 100ms = 100_000µs wall-clock. For 100% on N cores we'd need
|
||
// N * 100_000µs of CPU. Report 2× that to trigger the clamp.
|
||
mockTime = 1100;
|
||
const excessiveCpuUs = coreCount * 100_000 * 2;
|
||
mockCpu = { user: excessiveCpuUs, system: 0 };
|
||
|
||
const mem = {
|
||
rss: 100,
|
||
heapUsed: 50,
|
||
heapTotal: 80,
|
||
external: 10,
|
||
arrayBuffers: 0,
|
||
};
|
||
const sample = localRing.record(mem);
|
||
|
||
expect(sample.cpuPercent).toBe(100);
|
||
});
|
||
});
|