perf_hooks: emit trace events for marks, measures, and timerify

Adds the `node.perf.usertiming` trace events category for recording
usertiming marks and measures (e.g. `perf_hooks.performance.mark()`)
in the trace events timeline.

Adds the `node.perf.function` trace events category for recording
`perf_hooks.performance.timerify()` durations in the trace events
timeline.

PR-URL: https://github.com/nodejs/node/pull/18789
Reviewed-By: Ali Ijaz Sheikh <ofrobots@google.com>
Reviewed-By: Matteo Collina <matteo.collina@gmail.com>

1 files changed, 82 insertions, 0 deletions

diff --git a/test/parallel/test-trace-events-perf.js b/test/parallel/test-trace-events-perf.js
new file mode 100644
index 0000000000..e73579f87e
--- /dev/null
+++ b/test/parallel/test-trace-events-perf.js
@@ -0,0 +1,82 @@
+'use strict';
+const common = require('../common');
+const assert = require('assert');
+const cp = require('child_process');
+const path = require('path');
+const fs = require('fs');
+const tmpdir = require('../common/tmpdir');
+
+if (process.argv[2] === 'child') {
+  const { performance } = require('perf_hooks');
+
+  // Will emit mark and measure trace events
+  performance.mark('A');
+  setTimeout(() => {
+    performance.mark('B');
+    performance.measure('A to B', 'A', 'B');
+  }, 1);
+
+  // Intentional non-op, part of the test
+  function f() {}
+  const ff = performance.timerify(f);
+  ff();  // Will emit a timerify trace event
+} else {
+  tmpdir.refresh();
+  process.chdir(tmpdir.path);
+
+  const expectedMarks = ['A', 'B'];
+  const expectedBegins = [
+    { cat: 'node.perf,node.perf.timerify', name: 'f' },
+    { cat: 'node.perf,node.perf.usertiming', name: 'A to B' }
+  ];
+  const expectedEnds = [
+    { cat: 'node.perf,node.perf.timerify', name: 'f' },
+    { cat: 'node.perf,node.perf.usertiming', name: 'A to B' }
+  ];
+
+  const proc = cp.fork(__filename,
+                       [
+                         'child'
+                       ], {
+                         execArgv: [
+                           '--trace-events-enabled',
+                           '--trace-event-categories',
+                           'node.perf'
+                         ]
+                       });
+
+  proc.once('exit', common.mustCall(() => {
+    const file = path.join(tmpdir.path, 'node_trace.1.log');
+
+    assert(common.fileExists(file));
+    fs.readFile(file, common.mustCall((err, data) => {
+      const traces = JSON.parse(data.toString()).traceEvents;
+      assert.strictEqual(traces.length,
+                         expectedMarks.length +
+                         expectedBegins.length +
+                         expectedEnds.length);
+
+      traces.forEach((trace) => {
+        assert.strictEqual(trace.pid, proc.pid);
+        switch (trace.ph) {
+          case 'R':
+            assert.strictEqual(trace.cat, 'node.perf,node.perf.usertiming');
+            assert.strictEqual(trace.name, expectedMarks.shift());
+            break;
+          case 'b':
+            const expectedBegin = expectedBegins.shift();
+            assert.strictEqual(trace.cat, expectedBegin.cat);
+            assert.strictEqual(trace.name, expectedBegin.name);
+            break;
+          case 'e':
+            const expectedEnd = expectedEnds.shift();
+            assert.strictEqual(trace.cat, expectedEnd.cat);
+            assert.strictEqual(trace.name, expectedEnd.name);
+            break;
+          default:
+            assert.fail('Unexpected trace event phase');
+        }
+      });
+    }));
+  }));
+}