diff --git a/README.md b/README.md index 675eddea..a3799c34 100644 --- a/README.md +++ b/README.md @@ -97,14 +97,10 @@ Install [`pprof`][npm-url] with `npm` or add to your `package.json`. pprof -http=: heap.pb.gz ``` - * Collecting a heap profile with V8 allocation profile format: + * Collecting a heap profile with V8 allocation profile format: ```javascript - const profile = pprof.heap.v8Profile(pprof.heap.convertProfile); + const profile = await pprof.heap.v8Profile(); ``` - `v8Profile` accepts a callback and returns its result. Allocation nodes - are only valid during the callback, so copy/transform what you need - before returning. `heap.convertProfile` performs that conversion during - the callback, and `heap.profile()` uses it under the hood. [build-image]: https://github.com/Datadog/pprof-nodejs/actions/workflows/build.yml/badge.svg?branch=main [build-url]: https://github.com/Datadog/pprof-nodejs/actions/workflows/build.yml diff --git a/bindings/profilers/heap.cc b/bindings/profilers/heap.cc index ff7f2d01..a5e3c435 100644 --- a/bindings/profilers/heap.cc +++ b/bindings/profilers/heap.cc @@ -488,6 +488,23 @@ NAN_METHOD(HeapProfiler::StopSamplingHeapProfiler) { } } +// Signature: +// getAllocationProfile(): AllocationProfileNode +NAN_METHOD(HeapProfiler::GetAllocationProfile) { + auto isolate = info.GetIsolate(); + std::unique_ptr profile( + isolate->GetHeapProfiler()->GetAllocationProfile()); + if (!profile) { + return Nan::ThrowError("Heap profiler is not enabled."); + } + v8::AllocationProfile::Node* root = profile->GetRootNode(); + auto state = PerIsolateData::For(isolate)->GetHeapProfilerState(); + if (state) { + state->OnNewProfile(); + } + info.GetReturnValue().Set(TranslateAllocationProfile(root)); +} + // mapAllocationProfile(callback): callback result NAN_METHOD(HeapProfiler::MapAllocationProfile) { if (info.Length() < 1 || !info[0]->IsFunction()) { @@ -579,6 +596,7 @@ NAN_MODULE_INIT(HeapProfiler::Init) { heapProfiler, "startSamplingHeapProfiler", StartSamplingHeapProfiler); Nan::SetMethod( heapProfiler, "stopSamplingHeapProfiler", StopSamplingHeapProfiler); + Nan::SetMethod(heapProfiler, "getAllocationProfile", GetAllocationProfile); Nan::SetMethod(heapProfiler, "mapAllocationProfile", MapAllocationProfile); Nan::SetMethod(heapProfiler, "monitorOutOfMemory", MonitorOutOfMemory); Nan::Set(target, diff --git a/bindings/profilers/heap.hh b/bindings/profilers/heap.hh index d87e1cac..aef0ef7e 100644 --- a/bindings/profilers/heap.hh +++ b/bindings/profilers/heap.hh @@ -30,6 +30,10 @@ class HeapProfiler { // stopSamplingHeapProfiler() static NAN_METHOD(StopSamplingHeapProfiler); + // Signature: + // getAllocationProfile(): AllocationProfileNode + static NAN_METHOD(GetAllocationProfile); + // Signature: // mapAllocationProfile(callback): callback result static NAN_METHOD(MapAllocationProfile); diff --git a/bindings/profilers/wall.cc b/bindings/profilers/wall.cc index c4630ad3..0f21b56a 100644 --- a/bindings/profilers/wall.cc +++ b/bindings/profilers/wall.cc @@ -920,6 +920,28 @@ 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) { @@ -1078,6 +1100,20 @@ 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) { @@ -1112,6 +1148,7 @@ 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 4604a974..a68af759 100644 --- a/bindings/profilers/wall.hh +++ b/bindings/profilers/wall.hh @@ -157,6 +157,7 @@ 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); @@ -188,6 +189,7 @@ 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/bindings/translate-heap-profile.cc b/bindings/translate-heap-profile.cc index 0e795dd3..41f5e129 100644 --- a/bindings/translate-heap-profile.cc +++ b/bindings/translate-heap-profile.cc @@ -41,6 +41,30 @@ class HeapProfileTranslator : ProfileTranslator { #undef X public: + v8::Local TranslateAllocationProfile( + v8::AllocationProfile::Node* node) { + v8::Local children = NewArray(node->children.size()); + for (size_t i = 0; i < node->children.size(); i++) { + Set(children, i, TranslateAllocationProfile(node->children[i])); + } + + v8::Local allocations = NewArray(node->allocations.size()); + for (size_t i = 0; i < node->allocations.size(); i++) { + auto alloc = node->allocations[i]; + Set(allocations, + i, + CreateAllocation(NewNumber(alloc.count), NewNumber(alloc.size))); + } + + return CreateNode(node->name, + node->script_name, + NewInteger(node->script_id), + NewInteger(node->line_number), + NewInteger(node->column_number), + children, + allocations); + } + v8::Local TranslateAllocationProfile(Node* node) { v8::Local children = NewArray(node->children.size()); for (size_t i = 0; i < node->children.size(); i++) { @@ -118,6 +142,11 @@ std::shared_ptr TranslateAllocationProfileToCpp( return new_node; } +v8::Local TranslateAllocationProfile( + v8::AllocationProfile::Node* node) { + return HeapProfileTranslator().TranslateAllocationProfile(node); +} + v8::Local TranslateAllocationProfile(Node* node) { return HeapProfileTranslator().TranslateAllocationProfile(node); } diff --git a/bindings/translate-heap-profile.hh b/bindings/translate-heap-profile.hh index 22b644b7..e913dd66 100644 --- a/bindings/translate-heap-profile.hh +++ b/bindings/translate-heap-profile.hh @@ -39,4 +39,7 @@ std::shared_ptr TranslateAllocationProfileToCpp( v8::AllocationProfile::Node* node); v8::Local TranslateAllocationProfile(Node* node); +v8::Local TranslateAllocationProfile( + v8::AllocationProfile::Node* node); + } // namespace dd diff --git a/ts/src/heap-profiler-bindings.ts b/ts/src/heap-profiler-bindings.ts index 7d625d50..50d0e97b 100644 --- a/ts/src/heap-profiler-bindings.ts +++ b/ts/src/heap-profiler-bindings.ts @@ -37,6 +37,10 @@ export function stopSamplingHeapProfiler() { profiler.heapProfiler.stopSamplingHeapProfiler(); } +export function getAllocationProfile(): AllocationProfileNode { + return profiler.heapProfiler.getAllocationProfile(); +} + export function mapAllocationProfile( callback: (root: AllocationProfileNode) => T, ): T { diff --git a/ts/src/heap-profiler.ts b/ts/src/heap-profiler.ts index f34591ae..bb0f9c57 100644 --- a/ts/src/heap-profiler.ts +++ b/ts/src/heap-profiler.ts @@ -17,6 +17,7 @@ import {Profile} from 'pprof-format'; import { + getAllocationProfile, mapAllocationProfile, startSamplingHeapProfiler, stopSamplingHeapProfiler, @@ -33,6 +34,20 @@ import {isMainThread} from 'worker_threads'; let enabled = false; let heapIntervalBytes = 0; let heapStackDepth = 0; + +/* + * Collects a heap profile when heapProfiler is enabled. Otherwise throws + * an error. + * + * Data is returned in V8 allocation profile format. + */ +export function v8Profile(): AllocationProfileNode { + if (!enabled) { + throw new Error('Heap profiler is not enabled.'); + } + return getAllocationProfile(); +} + /** * Collects a heap profile when heapProfiler is enabled. Otherwise throws * an error. @@ -44,13 +59,35 @@ let heapStackDepth = 0; * @param callback - function to convert the heap profiler to a converted profile * @returns converted profile */ -export function v8Profile(callback: (root: AllocationProfileNode) => T): T { +export function v8ProfileV2( + callback: (root: AllocationProfileNode) => T, +): T { if (!enabled) { throw new Error('Heap profiler is not enabled.'); } return mapAllocationProfile(callback); } +/** + * Collects a profile and returns it serialized in pprof format. + * Throws if heap profiler is not enabled. + * + * @param ignoreSamplePath + * @param sourceMapper + */ +export function profile( + ignoreSamplePath?: string, + sourceMapper?: SourceMapper, + generateLabels?: GenerateAllocationLabelsFunction, +): Profile { + return convertProfile( + v8Profile(), + ignoreSamplePath, + sourceMapper, + generateLabels, + ); +} + export function convertProfile( rootNode: AllocationProfileNode, ignoreSamplePath?: string, @@ -93,12 +130,12 @@ export function convertProfile( * @param sourceMapper * @param generateLabels */ -export function profile( +export function profileV2( ignoreSamplePath?: string, sourceMapper?: SourceMapper, generateLabels?: GenerateAllocationLabelsFunction, ): Profile { - return v8Profile(root => { + return v8ProfileV2(root => { return convertProfile(root, ignoreSamplePath, sourceMapper, generateLabels); }); } diff --git a/ts/src/index.ts b/ts/src/index.ts index 92a7ec5c..73e85779 100644 --- a/ts/src/index.ts +++ b/ts/src/index.ts @@ -34,6 +34,7 @@ export const time = { profile: timeProfiler.profile, start: timeProfiler.start, stop: timeProfiler.stop, + profileV2: timeProfiler.profileV2, getContext: timeProfiler.getContext, setContext: timeProfiler.setContext, runWithContext: timeProfiler.runWithContext, @@ -49,6 +50,7 @@ export const heap = { start: heapProfiler.start, stop: heapProfiler.stop, profile: heapProfiler.profile, + profileV2: heapProfiler.profileV2, convertProfile: heapProfiler.convertProfile, v8Profile: heapProfiler.v8Profile, monitorOutOfMemory: heapProfiler.monitorOutOfMemory, diff --git a/ts/src/time-profiler.ts b/ts/src/time-profiler.ts index c53e87ee..1c023c0d 100644 --- a/ts/src/time-profiler.ts +++ b/ts/src/time-profiler.ts @@ -16,6 +16,7 @@ import {setTimeout} from 'timers/promises'; +import {Profile} from 'pprof-format'; import { serializeTimeProfile, GARBAGE_COLLECTION_FUNCTION_NAME, @@ -43,7 +44,7 @@ type Microseconds = number; type Milliseconds = number; type NativeTimeProfiler = InstanceType & { - stopAndCollect: ( + stopAndCollect?: ( restart: boolean, callback: (profile: TimeProfile) => T, ) => T; @@ -65,7 +66,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.stopAndCollect(false, () => undefined); + gProfiler.stop(false); gProfiler.start(); } } @@ -119,13 +120,22 @@ const DEFAULT_OPTIONS: TimeProfilerOptions = { useCPED: false, }; -export async function profile(options: TimeProfilerOptions = {}) { +export async function profile( + options: TimeProfilerOptions = {}, +): Promise { options = {...DEFAULT_OPTIONS, ...options}; start(options); await setTimeout(options.durationMillis!); 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}; @@ -148,11 +158,39 @@ export function start(options: TimeProfilerOptions = {}) { } } +export function stop( + restart = false, + generateLabels?: GenerateTimeLabelsFunction, + lowCardinalityLabels?: string[], +): Profile { + 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; +} + /** - * Serializes the profile inside a native callback while the V8 profile is - * still alive. This reduces memory overhead. + * 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. */ -export function stop( +export function stopV2( restart = false, generateLabels?: GenerateTimeLabelsFunction, lowCardinalityLabels?: string[], diff --git a/ts/test/heap-memory-worker.ts b/ts/test/heap-memory-worker.ts new file mode 100644 index 00000000..3e2fb1ae --- /dev/null +++ b/ts/test/heap-memory-worker.ts @@ -0,0 +1,112 @@ +import * as heapProfiler from '../src/heap-profiler'; +import * as v8HeapProfiler from '../src/heap-profiler-bindings'; +import {AllocationProfileNode} from '../src/v8-types'; + +const gc = (global as NodeJS.Global & {gc?: () => void}).gc; +if (!gc) { + throw new Error('Run with --expose-gc flag'); +} + +const keepAlive: object[] = []; + +// Create many unique functions via new Function() to produce a large profile tree. +function createAllocatorFunctions(count: number): Array<() => void> { + const fns: Array<() => void> = []; + for (let i = 0; i < count; i++) { + const fn = new Function( + 'keepAlive', + ` + for (let j = 0; j < 100; j++) { + keepAlive.push({ + id${i}: j, + data${i}: new Array(64).fill('${'x'.repeat(16)}'), + }); + } + `, + ) as (arr: object[]) => void; + fns.push(() => fn(keepAlive)); + } + return fns; +} + +function createDeepChain(depth: number): Array<(arr: object[]) => void> { + const fns: Array<(arr: object[]) => void> = []; + for (let i = depth - 1; i >= 0; i--) { + const next = i < depth - 1 ? fns[fns.length - 1] : null; + const fn = new Function( + 'keepAlive', + 'next', + ` + for (let j = 0; j < 50; j++) { + keepAlive.push({ arr${i}: new Array(32).fill(j) }); + } + if (next) next(keepAlive, null); + `, + ) as (arr: object[], next: unknown) => void; + fns.push((arr: object[]) => fn(arr, next)); + } + return fns; +} + +function generateAllocations(): void { + const wideFns = createAllocatorFunctions(5000); + for (const fn of wideFns) { + fn(); + } + + for (let chain = 0; chain < 200; chain++) { + const deepFns = createDeepChain(50); + deepFns[deepFns.length - 1](keepAlive); + } +} + +function traverseTree(root: AllocationProfileNode): void { + const stack: AllocationProfileNode[] = [root]; + while (stack.length > 0) { + const node = stack.pop()!; + if (node.children) { + for (const child of node.children) { + stack.push(child); + } + } + } +} + +function measureV1(): {initial: number; afterTraversal: number} { + gc!(); + gc!(); + const baseline = process.memoryUsage().heapUsed; + + const profile = v8HeapProfiler.getAllocationProfile(); + const initial = process.memoryUsage().heapUsed - baseline; + traverseTree(profile); + const afterTraversal = process.memoryUsage().heapUsed - baseline; + + return {initial, afterTraversal}; +} + +function measureV2(): {initial: number; afterTraversal: number} { + gc!(); + gc!(); + const baseline = process.memoryUsage().heapUsed; + + return v8HeapProfiler.mapAllocationProfile(root => { + const initial = process.memoryUsage().heapUsed - baseline; + traverseTree(root); + const afterTraversal = process.memoryUsage().heapUsed - baseline; + return {initial, afterTraversal}; + }); +} + +process.on('message', (version: 'v1' | 'v2') => { + heapProfiler.start(128, 128); + generateAllocations(); + + const {initial, afterTraversal} = + version === 'v1' ? measureV1() : measureV2(); + + heapProfiler.stop(); + keepAlive.length = 0; + + process.send!({initial, afterTraversal}); +}); diff --git a/ts/test/test-heap-profiler-v2.ts b/ts/test/test-heap-profiler-v2.ts new file mode 100644 index 00000000..c0ea5d9b --- /dev/null +++ b/ts/test/test-heap-profiler-v2.ts @@ -0,0 +1,130 @@ +import {strict as assert} from 'assert'; +import {fork} from 'child_process'; +import * as heapProfiler from '../src/heap-profiler'; +import * as v8HeapProfiler from '../src/heap-profiler-bindings'; + +function generateAllocations(): object[] { + const allocations: object[] = []; + for (let i = 0; i < 1000; i++) { + allocations.push({data: new Array(100).fill(i)}); + } + return allocations; +} + +describe('HeapProfiler V2 API', () => { + let keepAlive: object[] = []; + + before(() => { + heapProfiler.start(512, 64); + keepAlive = generateAllocations(); + }); + + after(() => { + heapProfiler.stop(); + keepAlive.length = 0; + }); + + describe('v8ProfileV2', () => { + it('should return AllocationProfileNode', () => { + heapProfiler.v8ProfileV2(root => { + assert.equal(typeof root.name, 'string'); + assert.equal(typeof root.scriptName, 'string'); + assert.equal(typeof root.scriptId, 'number'); + assert.equal(typeof root.lineNumber, 'number'); + assert.equal(typeof root.columnNumber, 'number'); + assert.ok(Array.isArray(root.allocations)); + + assert.ok(Array.isArray(root.children)); + assert.equal(typeof root.children.length, 'number'); + + if (root.children.length > 0) { + const child = root.children[0]; + assert.equal(typeof child.name, 'string'); + assert.ok(Array.isArray(child.children)); + assert.ok(Array.isArray(child.allocations)); + } + }); + }); + + it('should throw error when profiler not started', () => { + heapProfiler.stop(); + assert.throws( + () => { + heapProfiler.v8ProfileV2(() => {}); + }, + (err: Error) => { + return err.message === 'Heap profiler is not enabled.'; + }, + ); + heapProfiler.start(512, 64); + }); + }); + + describe('mapAllocationProfile', () => { + it('should return AllocationProfileNode directly', () => { + v8HeapProfiler.mapAllocationProfile(root => { + assert.equal(typeof root.name, 'string'); + assert.equal(typeof root.scriptName, 'string'); + assert.ok(Array.isArray(root.children)); + assert.ok(Array.isArray(root.allocations)); + }); + }); + }); + + describe('profileV2', () => { + it('should produce valid pprof Profile', () => { + const profile = heapProfiler.profileV2(); + + assert.ok(profile.sampleType); + assert.ok(profile.sample); + assert.ok(profile.location); + assert.ok(profile.function); + assert.ok(profile.stringTable); + }); + }); + + describe('Memory comparison', () => { + interface MemoryResult { + initial: number; + afterTraversal: number; + } + + function measureMemoryInWorker( + version: 'v1' | 'v2', + ): Promise { + return new Promise((resolve, reject) => { + const child = fork('./out/test/heap-memory-worker.js', [], { + execArgv: ['--expose-gc'], + }); + + child.on('message', (result: MemoryResult) => { + resolve(result); + child.kill(); + }); + + child.on('error', reject); + child.send(version); + }); + } + + it('mapAllocationProfile should use less initial memory than getAllocationProfile', async () => { + const v1MemoryUsage = await measureMemoryInWorker('v1'); + const v2MemoryUsage = await measureMemoryInWorker('v2'); + + console.log( + ` V1 initial: ${v1MemoryUsage.initial}, afterTraversal: ${v1MemoryUsage.afterTraversal} + | V2 initial: ${v2MemoryUsage.initial}, afterTraversal: ${v2MemoryUsage.afterTraversal}`, + ); + + assert.ok( + v2MemoryUsage.initial < v1MemoryUsage.initial, + `V2 initial should be less: V1=${v1MemoryUsage.initial}, V2=${v2MemoryUsage.initial}`, + ); + + assert.ok( + v2MemoryUsage.afterTraversal < v1MemoryUsage.afterTraversal, + `V2 afterTraversal should be less: V1=${v1MemoryUsage.afterTraversal}, V2=${v2MemoryUsage.afterTraversal}`, + ); + }).timeout(100_000); + }); +}); diff --git a/ts/test/test-heap-profiler.ts b/ts/test/test-heap-profiler.ts index 14f67d04..21fcddc2 100644 --- a/ts/test/test-heap-profiler.ts +++ b/ts/test/test-heap-profiler.ts @@ -35,30 +35,10 @@ import { const copy = require('deep-copy'); const assert = require('assert'); -function mapToGetterNode(node: AllocationProfileNode): AllocationProfileNode { - const children = (node.children || []).map(mapToGetterNode); - const allocations = node.allocations || []; - const result = {}; - - Object.defineProperties(result, { - name: {get: () => node.name}, - scriptName: {get: () => node.scriptName}, - scriptId: {get: () => node.scriptId}, - lineNumber: {get: () => node.lineNumber}, - columnNumber: {get: () => node.columnNumber}, - allocations: {get: () => allocations}, - children: {get: () => children}, - }); - return result as AllocationProfileNode; -} - describe('HeapProfiler', () => { let startStub: sinon.SinonStub<[number, number], void>; let stopStub: sinon.SinonStub<[], void>; - let profileStub: sinon.SinonStub< - [(root: AllocationProfileNode) => unknown], - unknown - >; + let profileStub: sinon.SinonStub<[], AllocationProfileNode>; let dateStub: sinon.SinonStub<[], number>; let memoryUsageStub: sinon.SinonStub<[], NodeJS.MemoryUsage>; beforeEach(() => { @@ -78,8 +58,8 @@ describe('HeapProfiler', () => { describe('profile', () => { it('should return a profile equal to the expected profile when external memory is allocated', async () => { profileStub = sinon - .stub(v8HeapProfiler, 'mapAllocationProfile') - .callsFake(callback => callback(mapToGetterNode(copy(v8HeapProfile)))); + .stub(v8HeapProfiler, 'getAllocationProfile') + .returns(copy(v8HeapProfile)); memoryUsageStub = sinon.stub(process, 'memoryUsage').returns({ external: 1024, rss: 2048, @@ -96,10 +76,8 @@ describe('HeapProfiler', () => { it('should return a profile equal to the expected profile when including all samples', async () => { profileStub = sinon - .stub(v8HeapProfiler, 'mapAllocationProfile') - .callsFake(callback => - callback(mapToGetterNode(copy(v8HeapWithPathProfile))), - ); + .stub(v8HeapProfiler, 'getAllocationProfile') + .returns(copy(v8HeapWithPathProfile)); memoryUsageStub = sinon.stub(process, 'memoryUsage').returns({ external: 0, rss: 2048, @@ -116,10 +94,8 @@ describe('HeapProfiler', () => { it('should return a profile equal to the expected profile when excluding profiler samples', async () => { profileStub = sinon - .stub(v8HeapProfiler, 'mapAllocationProfile') - .callsFake(callback => - callback(mapToGetterNode(copy(v8HeapWithPathProfile))), - ); + .stub(v8HeapProfiler, 'getAllocationProfile') + .returns(copy(v8HeapWithPathProfile)); memoryUsageStub = sinon.stub(process, 'memoryUsage').returns({ external: 0, rss: 2048, @@ -136,10 +112,8 @@ describe('HeapProfiler', () => { it('should return a profile equal to the expected profile when adding labels', async () => { profileStub = sinon - .stub(v8HeapProfiler, 'mapAllocationProfile') - .callsFake(callback => - callback(mapToGetterNode(copy(v8HeapWithPathProfile))), - ); + .stub(v8HeapProfiler, 'getAllocationProfile') + .returns(copy(v8HeapWithPathProfile)); memoryUsageStub = sinon.stub(process, 'memoryUsage').returns({ external: 0, rss: 2048, diff --git a/ts/test/test-time-profiler.ts b/ts/test/test-time-profiler.ts index 806a0b66..87c8e4a5 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 {stop} from '../src/time-profiler'; +import {profileV2, stopV2} from '../src/time-profiler'; import * as v8TimeProfiler from '../src/time-profiler-bindings'; import {timeProfile, v8TimeProfile} from './profiles-for-tests'; import {hrtime} from 'process'; @@ -25,6 +25,7 @@ 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'; @@ -439,12 +440,7 @@ describe('Time Profiler', () => { const sinonStubs: Array> = []; const timeProfilerStub = { start: sinon.stub(), - stopAndCollect: sinon - .stub() - .callsFake( - (_restart: boolean, cb: (p: typeof v8TimeProfile) => unknown) => - cb(v8TimeProfile), - ), + stop: sinon.stub().returns(v8TimeProfile), dispose: sinon.stub(), v8ProfilerStuckEventLoopDetected: sinon.stub().returns(0), }; @@ -479,7 +475,7 @@ describe('Time Profiler', () => { it('should be able to restart when stopping', async () => { time.start({intervalMicros: PROFILE_OPTIONS.intervalMicros}); timeProfilerStub.start.resetHistory(); - timeProfilerStub.stopAndCollect.resetHistory(); + timeProfilerStub.stop.resetHistory(); assert.deepEqual(timeProfile, time.stop(true)); assert.equal( @@ -489,19 +485,93 @@ describe('Time Profiler', () => { ); sinon.assert.notCalled(timeProfilerStub.start); - sinon.assert.calledOnce(timeProfilerStub.stopAndCollect); + sinon.assert.calledOnce(timeProfilerStub.stop); timeProfilerStub.start.resetHistory(); - timeProfilerStub.stopAndCollect.resetHistory(); + timeProfilerStub.stop.resetHistory(); assert.deepEqual(timeProfile, time.stop()); sinon.assert.notCalled(timeProfilerStub.start); - sinon.assert.calledOnce(timeProfilerStub.stopAndCollect); + sinon.assert.calledOnce(timeProfilerStub.stop); }); }); - describe('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(); + } + }); + }); + + describe('profileV2 (w/ stubs)', () => { // eslint-disable-next-line @typescript-eslint/no-explicit-any const sinonStubs: Array> = []; const timeProfilerStub = { @@ -531,7 +601,7 @@ describe('Time Profiler', () => { it('should profile during duration and finish profiling after duration', async () => { let isProfiling = true; - void time.profile(PROFILE_OPTIONS).then(() => { + void profileV2(PROFILE_OPTIONS).then(() => { isProfiling = false; }); await setTimeoutPromise(2 * PROFILE_OPTIONS.durationMillis); @@ -539,7 +609,7 @@ describe('Time Profiler', () => { }); it('should return a profile equal to the expected profile', async () => { - const profile = await time.profile(PROFILE_OPTIONS); + const profile = await profileV2(PROFILE_OPTIONS); assert.deepEqual(timeProfile, profile); }); @@ -548,7 +618,7 @@ describe('Time Profiler', () => { timeProfilerStub.start.resetHistory(); timeProfilerStub.stopAndCollect.resetHistory(); - assert.deepEqual(timeProfile, stop(true)); + assert.deepEqual(timeProfile, stopV2(true)); assert.equal( time.v8ProfilerStuckEventLoopDetected(), 0, @@ -560,7 +630,7 @@ describe('Time Profiler', () => { timeProfilerStub.start.resetHistory(); timeProfilerStub.stopAndCollect.resetHistory(); - assert.deepEqual(timeProfile, stop()); + assert.deepEqual(timeProfile, stopV2()); sinon.assert.notCalled(timeProfilerStub.start); sinon.assert.calledOnce(timeProfilerStub.stopAndCollect); }); @@ -571,12 +641,7 @@ describe('Time Profiler', () => { const sinonStubs: Array> = []; const timeProfilerStub = { start: sinon.stub(), - stopAndCollect: sinon - .stub() - .callsFake( - (_restart: boolean, cb: (p: typeof v8TimeProfile) => unknown) => - cb(v8TimeProfile), - ), + stop: sinon.stub().returns(v8TimeProfile), dispose: sinon.stub(), v8ProfilerStuckEventLoopDetected: sinon.stub().returns(2), }; @@ -598,7 +663,7 @@ describe('Time Profiler', () => { time.start(PROFILE_OPTIONS); time.stop(true); sinon.assert.calledTwice(timeProfilerStub.start); - sinon.assert.calledTwice(timeProfilerStub.stopAndCollect); + sinon.assert.calledTwice(timeProfilerStub.stop); assert.equal( time.v8ProfilerStuckEventLoopDetected(), @@ -606,16 +671,16 @@ describe('Time Profiler', () => { 'v8 bug not detected', ); timeProfilerStub.start.resetHistory(); - timeProfilerStub.stopAndCollect.resetHistory(); + timeProfilerStub.stop.resetHistory(); time.stop(false); sinon.assert.notCalled(timeProfilerStub.start); - sinon.assert.calledOnce(timeProfilerStub.stopAndCollect); + sinon.assert.calledOnce(timeProfilerStub.stop); }); }); describe('lowCardinalityLabels', () => { - it('should handle lowCardinalityLabels parameter in stop', async function testLowCardinalityLabels() { + it('should handle lowCardinalityLabels parameter in stop function', async function testLowCardinalityLabels() { if (unsupportedPlatform) { this.skip(); } @@ -697,9 +762,9 @@ describe('Time Profiler', () => { let foundHighCardLabel = false; const lowCardinalityLabels: Label[] = []; - for (const sample of profile.sample) { + profile.sample.forEach(sample => { if (sample.label && sample.label.length > 0) { - for (const label of sample.label) { + sample.label.forEach(label => { const keyStr = profile.stringTable.strings[Number(label.key)]; const valueStr = profile.stringTable.strings[Number(label.str)]; @@ -710,9 +775,9 @@ describe('Time Profiler', () => { if (keyStr === highCardLabel) { foundHighCardLabel = true; } - } + }); } - } + }); assert(foundLowCardLabel, 'Should find low cardinality label in samples'); assert( @@ -720,7 +785,8 @@ describe('Time Profiler', () => { 'Should find high cardinality label in samples', ); - // Verify that the lowCardinalityLabels parameter is working correctly. + // Verify that the lowCardinalityLabels parameter is working correctly + // This tests that the stop() function accepts and processes the lowCardinalityLabels parameter // Group labels by value and count them const labelsByValue = new Map(); @@ -798,6 +864,50 @@ 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 new file mode 100644 index 00000000..06de395f --- /dev/null +++ b/ts/test/time-memory-worker.ts @@ -0,0 +1,153 @@ +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); +});