From b9bab1cab66e822c3798c10e03cefa3ada779c58 Mon Sep 17 00:00:00 2001 From: Aaron Abbott Date: Fri, 21 Oct 2022 02:47:50 +0000 Subject: [PATCH] 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)); });