diff --git a/bindings/profilers/wall.cc b/bindings/profilers/wall.cc index 0f21b56a..c4630ad3 100644 --- a/bindings/profilers/wall.cc +++ b/bindings/profilers/wall.cc @@ -920,28 +920,6 @@ v8::ProfilerId WallProfiler::StartInternal() { return result.id; } -NAN_METHOD(WallProfiler::Stop) { - if (info.Length() != 1) { - return Nan::ThrowTypeError("Stop must have one argument."); - } - if (!info[0]->IsBoolean()) { - return Nan::ThrowTypeError("Restart must be a boolean."); - } - - bool restart = info[0].As()->Value(); - - WallProfiler* wallProfiler = - Nan::ObjectWrap::Unwrap(info.This()); - - v8::Local profile; - auto err = wallProfiler->StopImpl(restart, profile); - - if (!err.success) { - return Nan::ThrowTypeError(err.msg.c_str()); - } - info.GetReturnValue().Set(profile); -} - // stopAndCollect(restart, callback): callback result NAN_METHOD(WallProfiler::StopAndCollect) { if (info.Length() != 2) { @@ -1100,20 +1078,6 @@ Result WallProfiler::StopCore(bool restart, ProfileBuilder&& buildProfile) { return {}; } -Result WallProfiler::StopImpl(bool restart, v8::Local& profile) { - return StopCore(restart, - [&](const v8::CpuProfile* v8_profile, - bool hasCpuTime, - int64_t nonJSThreadsCpuTime, - ContextsByNode* contextsByNodePtr) { - profile = TranslateTimeProfile(v8_profile, - includeLines_, - contextsByNodePtr, - hasCpuTime, - nonJSThreadsCpuTime); - }); -} - Result WallProfiler::StopAndCollectImpl(bool restart, v8::Local callback, v8::Local& result) { @@ -1148,7 +1112,6 @@ NAN_MODULE_INIT(WallProfiler::Init) { SetContext); Nan::SetPrototypeMethod(tpl, "start", Start); - Nan::SetPrototypeMethod(tpl, "stop", Stop); Nan::SetPrototypeMethod(tpl, "stopAndCollect", StopAndCollect); Nan::SetPrototypeMethod(tpl, "dispose", Dispose); Nan::SetPrototypeMethod(tpl, diff --git a/bindings/profilers/wall.hh b/bindings/profilers/wall.hh index a68af759..4604a974 100644 --- a/bindings/profilers/wall.hh +++ b/bindings/profilers/wall.hh @@ -157,7 +157,6 @@ class WallProfiler : public Nan::ObjectWrap { v8::ProfilerId StartInternal(); template Result StopCore(bool restart, ProfileBuilder&& buildProfile); - Result StopImpl(bool restart, v8::Local& profile); Result StopAndCollectImpl(bool restart, v8::Local callback, v8::Local& result); @@ -189,7 +188,6 @@ class WallProfiler : public Nan::ObjectWrap { static NAN_METHOD(New); static NAN_METHOD(Start); - static NAN_METHOD(Stop); static NAN_METHOD(StopAndCollect); static NAN_METHOD(V8ProfilerStuckEventLoopDetected); static NAN_METHOD(Dispose); diff --git a/ts/src/index.ts b/ts/src/index.ts index 81cda61d..92a7ec5c 100644 --- a/ts/src/index.ts +++ b/ts/src/index.ts @@ -34,7 +34,6 @@ export const time = { profile: timeProfiler.profile, start: timeProfiler.start, stop: timeProfiler.stop, - profileV2: timeProfiler.profileV2, getContext: timeProfiler.getContext, setContext: timeProfiler.setContext, runWithContext: timeProfiler.runWithContext, diff --git a/ts/src/time-profiler.ts b/ts/src/time-profiler.ts index ed2fb4df..c53e87ee 100644 --- a/ts/src/time-profiler.ts +++ b/ts/src/time-profiler.ts @@ -43,7 +43,7 @@ type Microseconds = number; type Milliseconds = number; type NativeTimeProfiler = InstanceType & { - stopAndCollect?: ( + stopAndCollect: ( restart: boolean, callback: (profile: TimeProfile) => T, ) => T; @@ -65,7 +65,7 @@ function handleStopRestart() { // a loop eating 100% CPU, leading to empty profiles. // Fully stop and restart the profiler to reset the profile to a valid state. if (gV8ProfilerStuckEventLoopDetected > 0) { - gProfiler.stop(false); + gProfiler.stopAndCollect(false, () => undefined); gProfiler.start(); } } @@ -126,13 +126,6 @@ export async function profile(options: TimeProfilerOptions = {}) { return stop(); } -export async function profileV2(options: TimeProfilerOptions = {}) { - options = {...DEFAULT_OPTIONS, ...options}; - start(options); - await setTimeout(options.durationMillis!); - return stopV2(); -} - // Temporarily retained for backwards compatibility with older tracer export function start(options: TimeProfilerOptions = {}) { options = {...DEFAULT_OPTIONS, ...options}; @@ -155,39 +148,11 @@ export function start(options: TimeProfilerOptions = {}) { } } -export function stop( - restart = false, - generateLabels?: GenerateTimeLabelsFunction, - lowCardinalityLabels?: string[], -) { - if (!gProfiler) { - throw new Error('Wall profiler is not started'); - } - - const profile = gProfiler.stop(restart); - if (restart) { - handleStopRestart(); - } else { - handleStopNoRestart(); - } - - const serializedProfile = serializeTimeProfile( - profile, - gIntervalMicros, - gSourceMapper, - true, - generateLabels, - lowCardinalityLabels, - ); - return serializedProfile; -} - /** - * Same as stop() but uses the lazy callback path: serialization happens inside - * a native callback while the V8 profile is still alive. - * This reduces memory overhead. + * Serializes the profile inside a native callback while the V8 profile is + * still alive. This reduces memory overhead. */ -export function stopV2( +export function stop( restart = false, generateLabels?: GenerateTimeLabelsFunction, lowCardinalityLabels?: string[], diff --git a/ts/test/test-time-profiler.ts b/ts/test/test-time-profiler.ts index 87c8e4a5..806a0b66 100644 --- a/ts/test/test-time-profiler.ts +++ b/ts/test/test-time-profiler.ts @@ -16,7 +16,7 @@ import * as sinon from 'sinon'; import {time, getNativeThreadId} from '../src'; -import {profileV2, stopV2} from '../src/time-profiler'; +import {stop} from '../src/time-profiler'; import * as v8TimeProfiler from '../src/time-profiler-bindings'; import {timeProfile, v8TimeProfile} from './profiles-for-tests'; import {hrtime} from 'process'; @@ -25,7 +25,6 @@ import {AssertionError} from 'assert'; import {GenerateTimeLabelsArgs, LabelSet} from '../src/v8-types'; import {satisfies} from 'semver'; import {setTimeout as setTimeoutPromise} from 'timers/promises'; -import {fork} from 'child_process'; import assert from 'assert'; @@ -440,7 +439,12 @@ describe('Time Profiler', () => { const sinonStubs: Array> = []; const timeProfilerStub = { start: sinon.stub(), - stop: sinon.stub().returns(v8TimeProfile), + stopAndCollect: sinon + .stub() + .callsFake( + (_restart: boolean, cb: (p: typeof v8TimeProfile) => unknown) => + cb(v8TimeProfile), + ), dispose: sinon.stub(), v8ProfilerStuckEventLoopDetected: sinon.stub().returns(0), }; @@ -475,7 +479,7 @@ describe('Time Profiler', () => { it('should be able to restart when stopping', async () => { time.start({intervalMicros: PROFILE_OPTIONS.intervalMicros}); timeProfilerStub.start.resetHistory(); - timeProfilerStub.stop.resetHistory(); + timeProfilerStub.stopAndCollect.resetHistory(); assert.deepEqual(timeProfile, time.stop(true)); assert.equal( @@ -485,93 +489,19 @@ describe('Time Profiler', () => { ); sinon.assert.notCalled(timeProfilerStub.start); - sinon.assert.calledOnce(timeProfilerStub.stop); + sinon.assert.calledOnce(timeProfilerStub.stopAndCollect); timeProfilerStub.start.resetHistory(); - timeProfilerStub.stop.resetHistory(); + timeProfilerStub.stopAndCollect.resetHistory(); assert.deepEqual(timeProfile, time.stop()); sinon.assert.notCalled(timeProfilerStub.start); - sinon.assert.calledOnce(timeProfilerStub.stop); - }); - }); - - describe('profileV2', () => { - it('should exclude program and idle time', async () => { - const profile = await time.profileV2(PROFILE_OPTIONS); - assert.ok(profile.stringTable); - assert.equal(profile.stringTable.strings!.indexOf('(program)'), -1); - }); - - it('should preserve line-number root children metadata in lazy view', function () { - if (unsupportedPlatform) { - this.skip(); - } - - function hotPath() { - const end = hrtime.bigint() + 2_000_000n; - while (hrtime.bigint() < end); - } - - const profiler = new v8TimeProfiler.TimeProfiler({ - intervalMicros: 100, - durationMillis: 200, - lineNumbers: true, - withContexts: false, - workaroundV8Bug: false, - collectCpuTime: false, - collectAsyncId: false, - useCPED: false, - isMainThread: true, - }); - - profiler.start(); - try { - const deadline = Date.now() + 200; - while (Date.now() < deadline) { - hotPath(); - } - - let sawRootChildren = false; - let sawChildWithNonRootMetadata = false; - - // eslint-disable-next-line @typescript-eslint/no-explicit-any - profiler.stopAndCollect(false, (profile: any) => { - const root = profile.topDownRoot as { - name: string; - scriptName: string; - scriptId: number; - children: Array<{ - name: string; - scriptName: string; - scriptId: number; - }>; - }; - const children = root.children; - - sawRootChildren = children.length > 0; - sawChildWithNonRootMetadata = children.some( - child => - child.name !== root.name || - child.scriptName !== root.scriptName || - child.scriptId !== root.scriptId, - ); - return undefined; - }); - - assert(sawRootChildren, 'Expected root to have children'); - assert( - sawChildWithNonRootMetadata, - 'Line-number lazy root children should not collapse to root metadata', - ); - } finally { - profiler.dispose(); - } + sinon.assert.calledOnce(timeProfilerStub.stopAndCollect); }); }); - describe('profileV2 (w/ stubs)', () => { + describe('stop`', () => { // eslint-disable-next-line @typescript-eslint/no-explicit-any const sinonStubs: Array> = []; const timeProfilerStub = { @@ -601,7 +531,7 @@ describe('Time Profiler', () => { it('should profile during duration and finish profiling after duration', async () => { let isProfiling = true; - void profileV2(PROFILE_OPTIONS).then(() => { + void time.profile(PROFILE_OPTIONS).then(() => { isProfiling = false; }); await setTimeoutPromise(2 * PROFILE_OPTIONS.durationMillis); @@ -609,7 +539,7 @@ describe('Time Profiler', () => { }); it('should return a profile equal to the expected profile', async () => { - const profile = await profileV2(PROFILE_OPTIONS); + const profile = await time.profile(PROFILE_OPTIONS); assert.deepEqual(timeProfile, profile); }); @@ -618,7 +548,7 @@ describe('Time Profiler', () => { timeProfilerStub.start.resetHistory(); timeProfilerStub.stopAndCollect.resetHistory(); - assert.deepEqual(timeProfile, stopV2(true)); + assert.deepEqual(timeProfile, stop(true)); assert.equal( time.v8ProfilerStuckEventLoopDetected(), 0, @@ -630,7 +560,7 @@ describe('Time Profiler', () => { timeProfilerStub.start.resetHistory(); timeProfilerStub.stopAndCollect.resetHistory(); - assert.deepEqual(timeProfile, stopV2()); + assert.deepEqual(timeProfile, stop()); sinon.assert.notCalled(timeProfilerStub.start); sinon.assert.calledOnce(timeProfilerStub.stopAndCollect); }); @@ -641,7 +571,12 @@ describe('Time Profiler', () => { const sinonStubs: Array> = []; const timeProfilerStub = { start: sinon.stub(), - stop: sinon.stub().returns(v8TimeProfile), + stopAndCollect: sinon + .stub() + .callsFake( + (_restart: boolean, cb: (p: typeof v8TimeProfile) => unknown) => + cb(v8TimeProfile), + ), dispose: sinon.stub(), v8ProfilerStuckEventLoopDetected: sinon.stub().returns(2), }; @@ -663,7 +598,7 @@ describe('Time Profiler', () => { time.start(PROFILE_OPTIONS); time.stop(true); sinon.assert.calledTwice(timeProfilerStub.start); - sinon.assert.calledTwice(timeProfilerStub.stop); + sinon.assert.calledTwice(timeProfilerStub.stopAndCollect); assert.equal( time.v8ProfilerStuckEventLoopDetected(), @@ -671,16 +606,16 @@ describe('Time Profiler', () => { 'v8 bug not detected', ); timeProfilerStub.start.resetHistory(); - timeProfilerStub.stop.resetHistory(); + timeProfilerStub.stopAndCollect.resetHistory(); time.stop(false); sinon.assert.notCalled(timeProfilerStub.start); - sinon.assert.calledOnce(timeProfilerStub.stop); + sinon.assert.calledOnce(timeProfilerStub.stopAndCollect); }); }); describe('lowCardinalityLabels', () => { - it('should handle lowCardinalityLabels parameter in stop function', async function testLowCardinalityLabels() { + it('should handle lowCardinalityLabels parameter in stop', async function testLowCardinalityLabels() { if (unsupportedPlatform) { this.skip(); } @@ -762,9 +697,9 @@ describe('Time Profiler', () => { let foundHighCardLabel = false; const lowCardinalityLabels: Label[] = []; - profile.sample.forEach(sample => { + for (const sample of profile.sample) { if (sample.label && sample.label.length > 0) { - sample.label.forEach(label => { + for (const label of sample.label) { const keyStr = profile.stringTable.strings[Number(label.key)]; const valueStr = profile.stringTable.strings[Number(label.str)]; @@ -775,9 +710,9 @@ describe('Time Profiler', () => { if (keyStr === highCardLabel) { foundHighCardLabel = true; } - }); + } } - }); + } assert(foundLowCardLabel, 'Should find low cardinality label in samples'); assert( @@ -785,8 +720,7 @@ describe('Time Profiler', () => { 'Should find high cardinality label in samples', ); - // Verify that the lowCardinalityLabels parameter is working correctly - // This tests that the stop() function accepts and processes the lowCardinalityLabels parameter + // Verify that the lowCardinalityLabels parameter is working correctly. // Group labels by value and count them const labelsByValue = new Map(); @@ -864,50 +798,6 @@ describe('Time Profiler', () => { }); }); - describe('Memory comparison', () => { - interface WorkerMemoryResult { - initial: number; - afterTraversal: number; - afterHitCount: number; - } - - function measureMemoryInWorker( - version: 'v1' | 'v2', - ): Promise { - return new Promise((resolve, reject) => { - const child = fork('./out/test/time-memory-worker.js', [], { - execArgv: ['--expose-gc'], - }); - - child.on('message', (result: WorkerMemoryResult) => { - resolve(result); - child.kill(); - }); - - child.on('error', reject); - child.send(version); - }); - } - - it('stopAndCollect should use less memory than stop when profile is large', async function () { - if (unsupportedPlatform) { - this.skip(); - } - - const v1 = await measureMemoryInWorker('v1'); - const v2 = await measureMemoryInWorker('v2'); - - console.log('v1 : ', v1.initial, v1.afterTraversal, v1.afterHitCount); - console.log('v2 : ', v2.initial, v2.afterTraversal, v2.afterHitCount); - - // V2 creates almost nothing upfront — lazy wrappers vs full eager tree. - assert.ok( - v2.initial < v1.initial, - `V2 initial should be less: V1=${v1.initial}, V2=${v2.initial}`, - ); - }).timeout(120_000); - }); - describe('getNativeThreadId', () => { it('should return a number', () => { const threadId = getNativeThreadId(); diff --git a/ts/test/time-memory-worker.ts b/ts/test/time-memory-worker.ts deleted file mode 100644 index 06de395f..00000000 --- a/ts/test/time-memory-worker.ts +++ /dev/null @@ -1,153 +0,0 @@ -import {TimeProfiler} from '../src/time-profiler-bindings'; -import {ProfileNode, TimeProfile, TimeProfileNode} from '../src/v8-types'; -import {computeTotalHitCount} from '../src/profile-serializer'; - -const gc = (global as NodeJS.Global & {gc?: () => void}).gc; -if (!gc) { - throw new Error('Run with --expose-gc flag'); -} - -const SCRIPT_PADDING = 'a'.repeat(250); - -function createUniqueFunctions(count: number): Array<() => void> { - const fns: Array<() => void> = []; - for (let i = 0; i < count; i++) { - const fn = new Function( - `//# sourceURL=wide_fn_${i}_${SCRIPT_PADDING}.js\n` + - `var x${i}=0,e${i}=Date.now()+1;while(Date.now() void; - fns.push(fn); - } - return fns; -} - -function createDeepCallChain(chainId: number, depth: number): () => void { - let innermost: (() => void) | null = null; - for (let i = depth - 1; i >= 0; i--) { - const next = innermost; - innermost = new Function( - 'next', - `//# sourceURL=chain_${chainId}_d${i}_${SCRIPT_PADDING}.js\n` + - 'var c=0,e=Date.now()+1;while(Date.now() void; - } - return innermost!; -} - -const CHAIN_STRIDE = 30; - -function generateCpuWork( - wideFns: Array<() => void>, - deepChains: Array<() => void>, - durationMs: number, -): void { - const deadline = Date.now() + durationMs; - let i = 0; - while (Date.now() < deadline) { - wideFns[i % wideFns.length](); - if (i % CHAIN_STRIDE === 0) { - deepChains[(i / CHAIN_STRIDE) % deepChains.length](); - } - i++; - } -} - -const WIDE_FN_COUNT = 5000; -const CHAIN_COUNT = 100; -const CHAIN_DEPTH = 60; - -const PROFILER_OPTIONS = { - intervalMicros: 50, - durationMillis: 20_000, - lineNumbers: true, - withContexts: false, - workaroundV8Bug: false, - collectCpuTime: false, - collectAsyncId: false, - useCPED: false, - isMainThread: true, -}; - -function buildWorkload() { - const wideFns = createUniqueFunctions(WIDE_FN_COUNT); - const deepChains: Array<() => void> = []; - for (let c = 0; c < CHAIN_COUNT; c++) { - deepChains.push(createDeepCallChain(c, CHAIN_DEPTH)); - } - return {wideFns, deepChains}; -} - -function traverseTree(root: TimeProfileNode): void { - const stack: ProfileNode[] = [root]; - while (stack.length > 0) { - const node = stack.pop()!; - for (const child of node.children) { - stack.push(child); - } - } -} - -interface MemoryResult { - initial: number; - afterTraversal: number; - afterHitCount: number; -} - -function measureV1(): MemoryResult { - const {wideFns, deepChains} = buildWorkload(); - const profiler = new TimeProfiler(PROFILER_OPTIONS); - profiler.start(); - generateCpuWork(wideFns, deepChains, PROFILER_OPTIONS.durationMillis); - - gc!(); - const baseline = process.memoryUsage().heapUsed; - - const profile: TimeProfile = profiler.stop(false); - const initial = process.memoryUsage().heapUsed - baseline; - - traverseTree(profile.topDownRoot); - const afterTraversal = process.memoryUsage().heapUsed - baseline; - - // V1: computeTotalHitCount triggers children getters on every node, - // creating JS wrapper objects for a second full tree traversal. - computeTotalHitCount(profile.topDownRoot); - const afterHitCount = process.memoryUsage().heapUsed - baseline; - - profiler.dispose(); - return {initial, afterTraversal, afterHitCount}; -} - -function measureV2(): MemoryResult { - const {wideFns, deepChains} = buildWorkload(); - const profiler = new TimeProfiler(PROFILER_OPTIONS); - profiler.start(); - generateCpuWork(wideFns, deepChains, PROFILER_OPTIONS.durationMillis); - - gc!(); - const baseline = process.memoryUsage().heapUsed; - - const result = profiler.stopAndCollect( - false, - (profile: TimeProfile): MemoryResult => { - const initial = process.memoryUsage().heapUsed - baseline; - - traverseTree(profile.topDownRoot); - const afterTraversal = process.memoryUsage().heapUsed - baseline; - - // V2: totalHitCount is pre-computed in C++ — just a property read, - // no JS tree traversal, no wrapper objects created. - void profile.totalHitCount; - const afterHitCount = process.memoryUsage().heapUsed - baseline; - - return {initial, afterTraversal, afterHitCount}; - }, - ); - - profiler.dispose(); - return result; -} - -process.on('message', (version: 'v1' | 'v2') => { - const result = version === 'v1' ? measureV1() : measureV2(); - process.send!(result); -});