diff --git a/system-test/test.sh b/system-test/test.sh index 9c632f32..ce20a658 100755 --- a/system-test/test.sh +++ b/system-test/test.sh @@ -60,7 +60,7 @@ node --trace-warnings "$BENCHPATH" 10 $VERIFY_TIME_LINE_NUMBERS 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/index.ts b/ts/src/index.ts index 8f7bf9db..45b4d2f8 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 #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); + }); }); } diff --git a/ts/src/time-profiler-inspector.ts b/ts/src/time-profiler-inspector.ts new file mode 100644 index 00000000..28338ec2 --- /dev/null +++ b/ts/src/time-profiler-inspector.ts @@ -0,0 +1,117 @@ +/** + * 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. + * 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); + return; + } + session.post('Profiler.start', err => { + if (err !== null) { + reject(err); + return; + } + resolve(); + }); + }); + }); +} + +export function stopProfiling(): Promise { + return new Promise((resolve, reject) => { + session.post('Profiler.stop', (err, {profile}) => { + if (err !== null) { + reject(err); + return; + } + 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); + const scriptName = url.startsWith('file:/') ? url.slice(6) : url; + return { + name: functionName, + scriptName, + + // 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); + return; + } + resolve(); + } + ); + }); +} diff --git a/ts/src/time-profiler.ts b/ts/src/time-profiler.ts index f9296bc8..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'; @@ -22,7 +23,7 @@ import { setSamplingInterval, startProfiling, stopProfiling, -} from './time-profiler-bindings'; +} from './time-profiler-inspector'; let profiling = false; @@ -37,41 +38,29 @@ 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) { - const stop = start( +export async function profile( + options: TimeProfilerOptions +): Promise { + 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 +): Promise<() => Promise> { 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 +68,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)); });