From b9bab1cab66e822c3798c10e03cefa3ada779c58 Mon Sep 17 00:00:00 2001 From: Aaron Abbott Date: Fri, 21 Oct 2022 02:47:50 +0000 Subject: [PATCH 1/9] feat!: use inspector for time profiles --- ts/src/index.ts | 18 +++-- ts/src/time-profiler-inspector.ts | 113 ++++++++++++++++++++++++++++++ ts/src/time-profiler.ts | 25 +++---- ts/test/test-time-profiler.ts | 10 +-- 4 files changed, 140 insertions(+), 26 deletions(-) create mode 100644 ts/src/time-profiler-inspector.ts diff --git a/ts/src/index.ts b/ts/src/index.ts index 8f7bf9db..3a219fad 100644 --- a/ts/src/index.ts +++ b/ts/src/index.ts @@ -37,12 +37,16 @@ export const heap = { // If loaded with --require, start profiling. if (module.parent && module.parent.id === 'internal/preload') { - const stop = time.start(); - process.on('exit', () => { - // The process is going to terminate imminently. All work here needs to - // be synchronous. - const profile = stop(); - const buffer = encodeSync(profile); - writeFileSync(`pprof-profile-${process.pid}.pb.gz`, buffer); + time.start().then(stop => { + process.on('exit', async () => { + // The process is going to terminate imminently. All work here needs to + // be synchronous. + + // TODO: this code no longer works because stop() cannot be run synchronously. Maybe + // beforeExit event would be a decent middleground, or can run this in a signal handler. + const profile = await stop(); + const buffer = encodeSync(profile); + writeFileSync(`pprof-profile-${process.pid}.pb.gz`, buffer); + }); }); } diff --git a/ts/src/time-profiler-inspector.ts b/ts/src/time-profiler-inspector.ts new file mode 100644 index 00000000..7700b678 --- /dev/null +++ b/ts/src/time-profiler-inspector.ts @@ -0,0 +1,113 @@ +/** + * Copyright 2018 Google Inc. All Rights Reserved. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +import {TimeProfile, TimeProfileNode} from './v8-types'; +import * as inspector from 'node:inspector'; + +const session = new inspector.Session(); +session.connect(); + +// Wrappers around inspector functions +export function startProfiling(): Promise { + return new Promise((resolve, reject) => { + session.post('Profiler.enable', err => { + if (err !== null) { + reject(err); + } + session.post('Profiler.start', err => { + if (err !== null) { + reject(err); + } + resolve(); + }); + }); + }); +} + +export function stopProfiling(): Promise { + // return profiler.timeProfiler.stopProfiling(runName, includeLineInfo || false); + return new Promise((resolve, reject) => { + session.post('Profiler.stop', (err, {profile}) => { + if (err !== null) { + reject(err); + } + resolve(translateToTimeProfile(profile)); + }); + }); +} + +function translateToTimeProfile( + profile: inspector.Profiler.Profile +): TimeProfile { + const root: inspector.Profiler.ProfileNode | undefined = profile.nodes[0]; + // Not sure if this could ever happen... + if (root === undefined) { + return { + endTime: profile.endTime, + startTime: profile.startTime, + topDownRoot: { + children: [], + hitCount: 0, + scriptName: '', + }, + }; + } + + const nodesById: {[key: number]: inspector.Profiler.ProfileNode} = {}; + profile.nodes.forEach(node => (nodesById[node.id] = node)); + + function translateNode({ + hitCount, + children, + callFrame: {columnNumber, functionName, lineNumber, scriptId, url}, + }: inspector.Profiler.ProfileNode): TimeProfileNode { + const parsedScriptId = parseInt(scriptId); + return { + name: functionName, + scriptName: url, + + // Add 1 because these are zero-based + columnNumber: columnNumber + 1, + lineNumber: lineNumber + 1, + + hitCount: hitCount ?? 0, + scriptId: Number.isNaN(parsedScriptId) ? 0 : parsedScriptId, + children: + children?.map(childId => translateNode(nodesById[childId])) ?? [], + }; + } + + return { + endTime: profile.endTime, + startTime: profile.startTime, + topDownRoot: translateNode(root), + }; +} + +export function setSamplingInterval(intervalMicros: number): Promise { + return new Promise((resolve, reject) => { + session.post( + 'Profiler.setSamplingInterval', + {interval: intervalMicros}, + err => { + if (err !== null) { + reject(err); + } + resolve(); + } + ); + }); +} diff --git a/ts/src/time-profiler.ts b/ts/src/time-profiler.ts index f9296bc8..7d6b3a23 100644 --- a/ts/src/time-profiler.ts +++ b/ts/src/time-profiler.ts @@ -22,7 +22,7 @@ import { setSamplingInterval, startProfiling, stopProfiling, -} from './time-profiler-bindings'; +} from './time-profiler-inspector'; let profiling = false; @@ -49,29 +49,24 @@ export interface TimeProfilerOptions { } export async function profile(options: TimeProfilerOptions) { - const stop = start( + const stop = await start( options.intervalMicros || DEFAULT_INTERVAL_MICROS, - options.name, - options.sourceMapper, - options.lineNumbers + options.sourceMapper ); await delay(options.durationMillis); - return stop(); + return await stop(); } -export function start( +export async function start( intervalMicros: Microseconds = DEFAULT_INTERVAL_MICROS, - name?: string, - sourceMapper?: SourceMapper, - lineNumbers?: boolean + sourceMapper?: SourceMapper ) { if (profiling) { throw new Error('already profiling'); } profiling = true; - const runName = name || `pprof-${Date.now()}-${Math.random()}`; - setSamplingInterval(intervalMicros); + await setSamplingInterval(intervalMicros); // Node.js contains an undocumented API for reporting idle status to V8. // This lets the profiler distinguish idle time from time spent in native // code. Ideally this should be default behavior. Until then, use the @@ -79,10 +74,10 @@ export function start( // See https://github.com/nodejs/node/issues/19009#issuecomment-403161559. // eslint-disable-next-line @typescript-eslint/no-explicit-any (process as any)._startProfilerIdleNotifier(); - startProfiling(runName, lineNumbers); - return function stop() { + await startProfiling(); + return async function stop() { profiling = false; - const result = stopProfiling(runName, lineNumbers); + const result = await stopProfiling(); // eslint-disable-next-line @typescript-eslint/no-explicit-any (process as any)._stopProfilerIdleNotifier(); const profile = serializeTimeProfile(result, intervalMicros, sourceMapper); diff --git a/ts/test/test-time-profiler.ts b/ts/test/test-time-profiler.ts index b940080a..1740a01e 100644 --- a/ts/test/test-time-profiler.ts +++ b/ts/test/test-time-profiler.ts @@ -17,7 +17,7 @@ import delay from 'delay'; import * as sinon from 'sinon'; import * as time from '../src/time-profiler'; -import * as v8TimeProfiler from '../src/time-profiler-bindings'; +import * as inspectorTimeProfiler from '../src/time-profiler-inspector'; import {timeProfile, v8TimeProfile} from './profiles-for-tests'; const assert = require('assert'); @@ -46,11 +46,13 @@ describe('Time Profiler', () => { // eslint-disable-next-line @typescript-eslint/no-explicit-any const sinonStubs: Array> = []; before(() => { - sinonStubs.push(sinon.stub(v8TimeProfiler, 'startProfiling')); + sinonStubs.push(sinon.stub(inspectorTimeProfiler, 'startProfiling')); sinonStubs.push( - sinon.stub(v8TimeProfiler, 'stopProfiling').returns(v8TimeProfile) + sinon + .stub(inspectorTimeProfiler, 'stopProfiling') + .resolves(v8TimeProfile) ); - sinonStubs.push(sinon.stub(v8TimeProfiler, 'setSamplingInterval')); + sinonStubs.push(sinon.stub(inspectorTimeProfiler, 'setSamplingInterval')); sinonStubs.push(sinon.stub(Date, 'now').returns(0)); }); From f777979b8e324ac7826fc7016647710ea7afea63 Mon Sep 17 00:00:00 2001 From: Aaron Abbott Date: Fri, 21 Oct 2022 15:47:19 -0400 Subject: [PATCH 2/9] Apply suggestions from code review Co-authored-by: Punya Biswal --- ts/src/time-profiler-inspector.ts | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/ts/src/time-profiler-inspector.ts b/ts/src/time-profiler-inspector.ts index 7700b678..be42d32f 100644 --- a/ts/src/time-profiler-inspector.ts +++ b/ts/src/time-profiler-inspector.ts @@ -26,10 +26,12 @@ export function startProfiling(): Promise { session.post('Profiler.enable', err => { if (err !== null) { reject(err); + return; } session.post('Profiler.start', err => { if (err !== null) { reject(err); + return; } resolve(); }); @@ -43,6 +45,7 @@ export function stopProfiling(): Promise { session.post('Profiler.stop', (err, {profile}) => { if (err !== null) { reject(err); + return; } resolve(translateToTimeProfile(profile)); }); @@ -105,6 +108,7 @@ export function setSamplingInterval(intervalMicros: number): Promise { err => { if (err !== null) { reject(err); + return; } resolve(); } From 6fd2c761bf607c6e5d1ac3f57c7ef9ba034156cd Mon Sep 17 00:00:00 2001 From: Aaron Abbott Date: Mon, 24 Oct 2022 15:44:50 +0000 Subject: [PATCH 3/9] Small fixes --- package-lock.json | 2 +- ts/src/time-profiler-inspector.ts | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/package-lock.json b/package-lock.json index b6311d03..700407d1 100644 --- a/package-lock.json +++ b/package-lock.json @@ -44,7 +44,7 @@ "typescript": "~4.3.0" }, "engines": { - "node": ">=10.4.1" + "node": ">=14.0.0" } }, "node_modules/@babel/code-frame": { diff --git a/ts/src/time-profiler-inspector.ts b/ts/src/time-profiler-inspector.ts index be42d32f..96a1829f 100644 --- a/ts/src/time-profiler-inspector.ts +++ b/ts/src/time-profiler-inspector.ts @@ -1,5 +1,5 @@ /** - * Copyright 2018 Google Inc. All Rights Reserved. + * Copyright 2022 Google Inc. All Rights Reserved. * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. From f411224b641e5cf5d21912ce7e4941c0f73693f0 Mon Sep 17 00:00:00 2001 From: Aaron Abbott Date: Mon, 24 Oct 2022 16:19:20 +0000 Subject: [PATCH 4/9] More fixes --- ts/src/time-profiler-inspector.ts | 1 - 1 file changed, 1 deletion(-) diff --git a/ts/src/time-profiler-inspector.ts b/ts/src/time-profiler-inspector.ts index 96a1829f..33a686cf 100644 --- a/ts/src/time-profiler-inspector.ts +++ b/ts/src/time-profiler-inspector.ts @@ -40,7 +40,6 @@ export function startProfiling(): Promise { } export function stopProfiling(): Promise { - // return profiler.timeProfiler.stopProfiling(runName, includeLineInfo || false); return new Promise((resolve, reject) => { session.post('Profiler.stop', (err, {profile}) => { if (err !== null) { From 7211b6da90396dbb5b9e9ce4e634771896d20bf7 Mon Sep 17 00:00:00 2001 From: Aaron Abbott Date: Wed, 2 Nov 2022 04:00:26 +0000 Subject: [PATCH 5/9] Strip file:/ prefixes from scriptNames and fixed system tests The inspector approach uses [`CpuProfilingMode::kLeafNodeLineNumbers`](https://source.chromium.org/chromium/chromium/src/+/main:v8/include/v8-profiler.h;l=244;drc=27e39fa1dd71076618c358639ed8a327bc3873c4) under the hood which changes the line numbering scheme. I updated the tests to expect the new line number. --- system-test/test.sh | 7 ++++--- ts/src/time-profiler-inspector.ts | 3 ++- 2 files changed, 6 insertions(+), 4 deletions(-) diff --git a/system-test/test.sh b/system-test/test.sh index 9c632f32..d2666548 100755 --- a/system-test/test.sh +++ b/system-test/test.sh @@ -2,8 +2,8 @@ SRCDIR="/cloned_src" -trap "cd $SRCDIR && npm run clean" EXIT -trap "echo '** TEST FAILED **'" ERR +# trap "cd $SRCDIR && npm run clean" EXIT +# trap "echo '** TEST FAILED **'" ERR function timeout_after() { # timeout on Node 11 alpine image requires -t to specify time. @@ -57,10 +57,11 @@ fi node -v node --trace-warnings "$BENCHPATH" 10 $VERIFY_TIME_LINE_NUMBERS +ls if [[ "$VERIFY_TIME_LINE_NUMBERS" == "true" ]]; then pprof -lines -top -nodecount=2 time.pb.gz | tee $tty | \ - grep "busyLoop.*src/busybench.js:[2-3][08-9]" + grep "busyLoop.*src/busybench.js:27" pprof -filefunctions -top -nodecount=2 heap.pb.gz | tee $tty | \ grep "busyLoop.*src/busybench.js" else diff --git a/ts/src/time-profiler-inspector.ts b/ts/src/time-profiler-inspector.ts index 33a686cf..28338ec2 100644 --- a/ts/src/time-profiler-inspector.ts +++ b/ts/src/time-profiler-inspector.ts @@ -77,9 +77,10 @@ function translateToTimeProfile( callFrame: {columnNumber, functionName, lineNumber, scriptId, url}, }: inspector.Profiler.ProfileNode): TimeProfileNode { const parsedScriptId = parseInt(scriptId); + const scriptName = url.startsWith('file:/') ? url.slice(6) : url; return { name: functionName, - scriptName: url, + scriptName, // Add 1 because these are zero-based columnNumber: columnNumber + 1, From b5483e357b222eac4b2c0e8615669d7e7c263ede Mon Sep 17 00:00:00 2001 From: Aaron Abbott Date: Wed, 2 Nov 2022 04:09:26 +0000 Subject: [PATCH 6/9] Remove unnused options since we are already making breaking changes for v4 --- ts/src/time-profiler.ts | 9 --------- 1 file changed, 9 deletions(-) diff --git a/ts/src/time-profiler.ts b/ts/src/time-profiler.ts index 7d6b3a23..796b96a8 100644 --- a/ts/src/time-profiler.ts +++ b/ts/src/time-profiler.ts @@ -37,15 +37,6 @@ export interface TimeProfilerOptions { /** average time in microseconds between samples */ intervalMicros?: Microseconds; sourceMapper?: SourceMapper; - name?: string; - - /** - * This configuration option is experimental. - * When set to true, functions will be aggregated at the line level, rather - * than at the function level. - * This defaults to false. - */ - lineNumbers?: boolean; } export async function profile(options: TimeProfilerOptions) { From c844b8d7ee9c6b56805e82514da11ac9dd70fbcb Mon Sep 17 00:00:00 2001 From: Aaron Abbott Date: Wed, 2 Nov 2022 04:17:24 +0000 Subject: [PATCH 7/9] Add todo for --require --- ts/src/index.ts | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/ts/src/index.ts b/ts/src/index.ts index 3a219fad..45b4d2f8 100644 --- a/ts/src/index.ts +++ b/ts/src/index.ts @@ -42,8 +42,8 @@ if (module.parent && module.parent.id === 'internal/preload') { // The process is going to terminate imminently. All work here needs to // be synchronous. - // TODO: this code no longer works because stop() cannot be run synchronously. Maybe - // beforeExit event would be a decent middleground, or can run this in a signal handler. + // TODO #234: this code no longer works because stop() cannot be run synchronously. + // Remove this feature. const profile = await stop(); const buffer = encodeSync(profile); writeFileSync(`pprof-profile-${process.pid}.pb.gz`, buffer); From b510c6e4545c4f078fe8cb3ab57a50b55e2398f7 Mon Sep 17 00:00:00 2001 From: Aaron Abbott Date: Wed, 2 Nov 2022 04:19:59 +0000 Subject: [PATCH 8/9] Undo accidental edits to system test --- system-test/test.sh | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/system-test/test.sh b/system-test/test.sh index d2666548..ce20a658 100755 --- a/system-test/test.sh +++ b/system-test/test.sh @@ -2,8 +2,8 @@ SRCDIR="/cloned_src" -# trap "cd $SRCDIR && npm run clean" EXIT -# trap "echo '** TEST FAILED **'" ERR +trap "cd $SRCDIR && npm run clean" EXIT +trap "echo '** TEST FAILED **'" ERR function timeout_after() { # timeout on Node 11 alpine image requires -t to specify time. @@ -57,7 +57,6 @@ fi node -v node --trace-warnings "$BENCHPATH" 10 $VERIFY_TIME_LINE_NUMBERS -ls if [[ "$VERIFY_TIME_LINE_NUMBERS" == "true" ]]; then pprof -lines -top -nodecount=2 time.pb.gz | tee $tty | \ From 3650dbc2fb05fb1e5f91a462d038e7efae9b11d3 Mon Sep 17 00:00:00 2001 From: Aaron Abbott Date: Wed, 2 Nov 2022 04:28:37 +0000 Subject: [PATCH 9/9] Add explicit signatures to modified functions to make breaking changes more clear going forward --- ts/src/time-profiler.ts | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/ts/src/time-profiler.ts b/ts/src/time-profiler.ts index 796b96a8..12b132ce 100644 --- a/ts/src/time-profiler.ts +++ b/ts/src/time-profiler.ts @@ -15,6 +15,7 @@ */ import delay from 'delay'; +import type {perftools} from '../../proto/profile'; import {serializeTimeProfile} from './profile-serializer'; import {SourceMapper} from './sourcemapper/sourcemapper'; @@ -39,7 +40,9 @@ export interface TimeProfilerOptions { sourceMapper?: SourceMapper; } -export async function profile(options: TimeProfilerOptions) { +export async function profile( + options: TimeProfilerOptions +): Promise { const stop = await start( options.intervalMicros || DEFAULT_INTERVAL_MICROS, options.sourceMapper @@ -51,7 +54,7 @@ export async function profile(options: TimeProfilerOptions) { export async function start( intervalMicros: Microseconds = DEFAULT_INTERVAL_MICROS, sourceMapper?: SourceMapper -) { +): Promise<() => Promise> { if (profiling) { throw new Error('already profiling'); }