Track require() source locations and additional metadata (#10)

- After running `trackRequires(true, { trackSource: true });`, the `require()` traces will now have an `args` object which contains the source location which can be rendered as a table in the <https://ui.perfetto.dev> view.
- Metadata for other measurements can be passed using the <https://developer.mozilla.org/en-US/docs/Web/API/Performance/measure#detail> property and it would be set as the `args` object on the trace object.

Signed-off-by: Darshan Sen <[email protected]>

README.md

@@ -46,7 +46,7 @@ process.on("beforeExit", () => {
 });
 
 // Enables tracking require() calls.
-trackRequires(true);
+trackRequires(true, { trackSource: true });
 
 // The assert module takes milliseconds to load, so it would be distinctly
 // visible in the performance trace.

docs/api/README.md

@@ -20,19 +20,23 @@ Call `traceEvents.getEvents()` to get the PerformanceEntry objects in the [Trace
     "ph": "X",
     "pid": 1,
     "ts": 34509,
-    "dur": 1004141
+    "dur": 1004141,
+    "args": null
   },
   {
     "name": "A",
     "cat": "measure",
     "ph": "X",
     "pid": 1,
     "ts": 33837,
-    "dur": 2002098
+    "dur": 2002098,
+    "args": { "foo": "bar" }
   }
 ]
 ```
 
-## `trackRequires(bool)` (only available in [CommonJS](https://nodejs.org/api/modules.html#modules-commonjs-modules))
+## `trackRequires(switch, options)` (only available in [CommonJS](https://nodejs.org/api/modules.html#modules-commonjs-modules))
 
-Call `trackRequires(true)` to enable tracking `require()`s and call `trackRequires(false)` to disable tracking `require()`s.
+- `switch` (**bool**) - Call `trackRequires(true)` to enable tracking `require()`s and call `trackRequires(false)` to disable tracking `require()`s.
+- `options` (**object**)
+  - `trackSource` (**bool**) - Call `trackRequires(true, { trackSource: true })` to enable tracking `require()`s and also capture the source locations. This creates a throw-away error object and parses the `stack` property, so it introduces an overhead.

docs/examples/tracing-requires/README.md

@@ -8,7 +8,7 @@ Before the process exits, the `TraceEvents` object is destroyed and the trace ev
 
 https://github.com/RaisinTen/perftrace/blob/7cb1ce34d19ed8816e15094b3ef4fd03bb157c76/docs/examples/tracing-requires/index.js#L6-L10
 
-The `require()` calls can be tracked by passing `true` to `trackRequires()` like it is being done in:
+The `require()` calls can be tracked by calling `trackRequires()` like it is being done in:
 
 https://github.com/RaisinTen/perftrace/blob/7cb1ce34d19ed8816e15094b3ef4fd03bb157c76/docs/examples/tracing-requires/index.js#L12
 

docs/examples/tracing-requires/index.js

@@ -9,7 +9,7 @@ process.on("beforeExit", () => {
   writeFileSync("events.json", JSON.stringify(events));
 });
 
-trackRequires(true);
+trackRequires(true, { trackSource: true });
 
 // Express Hello world example
 // Refs: https://expressjs.com/en/starter/hello-world.html

index.cjs

@@ -1,5 +1,17 @@
 const { PerformanceObserver, performance } = require('node:perf_hooks');
 
+function getSource() {
+  const error = new Error();
+  const stack = error.stack.split("\n");
+  // Ignore the first 3 elements of the error stack to get the relevant source:
+  // Error
+  //     at getSource (.../perftrace/index.cjs:...:...)
+  //     at Module.require (.../perftrace/index.cjs:...:...)
+  //     ...
+  const source = stack.slice(3);
+  return source;
+}
+
 class TraceEvents {
   _eventObjects;
   _observer;
@@ -16,6 +28,7 @@ class TraceEvents {
           pid: 1,
           ts: Math.round(measure.startTime * 1000),
           dur: Math.round(measure.duration * 1000),
+          args: measure.detail,
         });
       });
     });
@@ -37,12 +50,21 @@ class TraceEvents {
 const Module = require('module');
 const originalRequire = Module.prototype.require;
 
-function trackRequires(shouldTrackRequires) {
+function trackRequires(shouldTrackRequires, options) {
   if (shouldTrackRequires) {
     Module.prototype.require = function () {
+      let source = null;
+      if (options?.trackSource) {
+        source = getSource();
+      }
       performance.mark(`require("${arguments[0]}")`);
       const ret = originalRequire.apply(this, arguments);
-      performance.measure(`require("${arguments[0]}")`, `require("${arguments[0]}")`);
+      performance.measure(
+        `require("${arguments[0]}")`,
+        {
+          detail: source,
+          start: `require("${arguments[0]}")`,
+        });
       return ret;
     };
   } else {

test/node-test.cjs

@@ -1,4 +1,4 @@
-const { ok } = require("node:assert");
+const { ok, deepStrictEqual, strictEqual } = require("node:assert");
 const { TraceEvents, trackRequires } = require("../index.cjs");
 const { after, before, describe, test } = require("node:test");
 const { performance } = require("node:perf_hooks");
@@ -73,6 +73,10 @@ describe("track requires", async () => {
     traceEvents = new TraceEvents();
     trackRequires(true);
     require("node:tls");
+    trackRequires(true, { trackSource: true });
+    require("node:os");
+    trackRequires(true, { trackSource: false });
+    require("node:async_hooks");
     trackRequires(false);
     require("node:net");
 
@@ -83,10 +87,68 @@ describe("track requires", async () => {
     const events = traceEvents.getEvents();
     const requireTls = events.find((element) => element.name === `require("node:tls")`);
     ok(requireTls);
+    const requireOs = events.find((element) => element.name === `require("node:os")`);
+    ok(requireOs);
+    const requireAsyncHooks = events.find((element) => element.name === `require("node:async_hooks")`);
+    ok(requireAsyncHooks);
     const requireNet = events.find((element) => element.name === `require("node:net")`);
     ok(!requireNet);
   });
 
+  test("source location", () => {
+    const events = traceEvents.getEvents();
+
+    const requireTls = events.find((element) => element.name === `require("node:tls")`);
+    ok(requireTls);
+    strictEqual(requireTls.args, null);
+
+    const requireOs = events.find((element) => element.name === `require("node:os")`);
+    ok(requireOs);
+    ok(requireOs.args);
+    ok(requireOs.args.length > 5);
+    ok(requireOs.args[1].includes(__filename));
+
+    const requireAsyncHooks = events.find((element) => element.name === `require("node:async_hooks")`);
+    ok(requireAsyncHooks);
+    strictEqual(requireAsyncHooks.args, null);
+  });
+
+  after(() => {
+    traceEvents.destroy();
+  });
+});
+
+describe("metadata", async () => {
+  let traceEvents;
+  const metadata = { foo: "bar", number: 2 };
+
+  await before(async () => {
+    return new Promise((resolve, reject) => {
+      setTimeout(() => {
+        resolve();
+      }, 2000);
+
+      traceEvents = new TraceEvents();
+
+      performance.mark("UwU");
+      setTimeout(() => {
+        performance.measure(
+          "UwU",
+          {
+            detail: metadata,
+            start: "UwU",
+          });
+      }, 1000);
+    });
+  });
+
+  test("check metadata", () => {
+    const events = traceEvents.getEvents();
+    const UwU = events.find((element) => element.name === "UwU");
+    ok(UwU);
+    deepStrictEqual(UwU.args, metadata);
+  });
+
   after(() => {
     traceEvents.destroy();
   });