feat!: use inspector for time profiles

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

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);
+    });
   });
 }

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<void> {
+  return new Promise<void>((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<TimeProfile> {
+  return new Promise<TimeProfile>((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<void> {
+  return new Promise<void>((resolve, reject) => {
+    session.post(
+      'Profiler.setSamplingInterval',
+      {interval: intervalMicros},
+      err => {
+        if (err !== null) {
+          reject(err);
+          return;
+        }
+        resolve();
+      }
+    );
+  });
+}

ts/src/time-profiler.ts

@@ -15,14 +15,15 @@
  */
 
 import delay from 'delay';
+import type {perftools} from '../../proto/profile';
 
 import {serializeTimeProfile} from './profile-serializer';
 import {SourceMapper} from './sourcemapper/sourcemapper';
 import {
   setSamplingInterval,
   startProfiling,
   stopProfiling,
-} from './time-profiler-bindings';
+} from './time-profiler-inspector';
 
 let profiling = false;
 
@@ -37,52 +38,40 @@ 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<perftools.profiles.IProfile> {
+  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<perftools.profiles.IProfile>> {
   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
   // undocumented API.
   // 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);

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<sinon.SinonStub<any, any>> = [];
     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));
     });