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>

doc/api/perf_hooks.md

@@ -268,8 +268,8 @@ added: v8.5.0
 
 * {string}
 
-The type of the performance entry. Current it may be one of: `'node'`, `'mark'`,
+The type of the performance entry. Currently it may be one of: `'node'`,
-`'measure'`, `'gc'`, or `'function'`.
+`'mark'`, `'measure'`, `'gc'`, or `'function'`.
 
 ### performanceEntry.kind
 <!-- YAML

doc/api/tracing.md

@@ -10,8 +10,20 @@ starting a Node.js application.
 
 The set of categories for which traces are recorded can be specified using the
 `--trace-event-categories` flag followed by a list of comma separated category
-names. By default the `node`, `node.async_hooks`, and `v8` categories are
+names.
-enabled.
+
+The available categories are:
+
+* `node`
+* `node.async_hooks` - Enables capture of detailed async_hooks trace data.
+* `node.perf` - Enables capture of [Performance API] measurements.
+  * `node.perf.usertiming` - Enables capture of only Performance API User Timing
+    measures and marks.
+  * `node.perf.timerify` - Enables capture of only Performance API timerify
+    measurements.
+* `v8`
+
+By default the `node`, `node.async_hooks`, and `v8` categories are enabled.
 
 ```txt
 node --trace-events-enabled --trace-event-categories v8,node,node.async_hooks server.js
@@ -24,3 +36,5 @@ tab of Chrome.
 Starting with Node 10.0.0, the tracing system uses the same time source as the
 one used by `process.hrtime()` however the trace-event timestamps are expressed
 in microseconds, unlike `process.hrtime()` which returns nanoseconds.
+
+[Performance API]: perf_hooks.html

src/node_perf.cc

@@ -105,8 +105,8 @@ void Mark(const FunctionCallbackInfo<Value>& args) {
   auto marks = env->performance_marks();
   (*marks)[*name] = now;
 
-  // TODO(jasnell): Once Tracing API is fully implemented, this should
+  TRACE_EVENT_COPY_MARK_WITH_TIMESTAMP(
-  // record a trace event also.
+      "node.perf,node.perf.usertiming", *name, now / 1000);
 
   PerformanceEntry entry(env, *name, "mark", now, now);
   Local<Object> obj = entry.ToObject();
@@ -153,8 +153,10 @@ void Measure(const FunctionCallbackInfo<Value>& args) {
   if (endTimestamp < startTimestamp)
     endTimestamp = startTimestamp;
 
-  // TODO(jasnell): Once Tracing API is fully implemented, this should
+  TRACE_EVENT_COPY_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
-  // record a trace event also.
+      "node.perf,node.perf.usertiming", *name, *name, startTimestamp / 1000);
+  TRACE_EVENT_COPY_NESTABLE_ASYNC_END_WITH_TIMESTAMP0(
+      "node.perf,node.perf.usertiming", *name, *name, endTimestamp / 1000);
 
   PerformanceEntry entry(env, *name, "measure", startTimestamp, endTimestamp);
   Local<Object> obj = entry.ToObject();
@@ -269,10 +271,15 @@ void TimerFunctionCall(const FunctionCallbackInfo<Value>& args) {
   v8::TryCatch try_catch(isolate);
   if (args.IsConstructCall()) {
     start = PERFORMANCE_NOW();
+    TRACE_EVENT_COPY_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
+        "node.perf,node.perf.timerify", *name, *name, start / 1000);
     v8::MaybeLocal<Object> ret = fn->NewInstance(context,
                                                  call_args.size(),
                                                  call_args.data());
     end = PERFORMANCE_NOW();
+    TRACE_EVENT_COPY_NESTABLE_ASYNC_END_WITH_TIMESTAMP0(
+        "node.perf,node.perf.timerify", *name, *name, end / 1000);
+
     if (ret.IsEmpty()) {
       try_catch.ReThrow();
       return;
@@ -280,11 +287,16 @@ void TimerFunctionCall(const FunctionCallbackInfo<Value>& args) {
     args.GetReturnValue().Set(ret.ToLocalChecked());
   } else {
     start = PERFORMANCE_NOW();
+    TRACE_EVENT_COPY_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
+        "node.perf,node.perf.timerify", *name, *name, start / 1000);
     v8::MaybeLocal<Value> ret = fn->Call(context,
                                          args.This(),
                                          call_args.size(),
                                          call_args.data());
     end = PERFORMANCE_NOW();
+    TRACE_EVENT_COPY_NESTABLE_ASYNC_END_WITH_TIMESTAMP0(
+        "node.perf,node.perf.timerify", *name, *name, end / 1000);
+
     if (ret.IsEmpty()) {
       try_catch.ReThrow();
       return;

src/node_perf.h

@@ -4,6 +4,7 @@
 #if defined(NODE_WANT_INTERNALS) && NODE_WANT_INTERNALS
 
 #include "node.h"
+#include "node_internals.h"
 #include "node_perf_common.h"
 #include "env.h"
 #include "base_object-inl.h"

src/tracing/trace_event.h

@@ -246,7 +246,18 @@ enum CategoryGroupEnabledFlags {
 // Implemented.
 #define INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMP(                  \
     phase, category_group, name, id, thread_id, timestamp, flags, ...)       \
-  UNIMPLEMENTED()
+  do {                                                                       \
+    INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category_group);                  \
+    if (INTERNAL_TRACE_EVENT_CATEGORY_GROUP_ENABLED_FOR_RECORDING_MODE()) {  \
+      unsigned int trace_event_flags = flags | TRACE_EVENT_FLAG_HAS_ID;      \
+      node::tracing::TraceID trace_event_trace_id(id,                        \
+                                                  &trace_event_flags);       \
+      node::tracing::AddTraceEventWithTimestamp(                             \
+          phase, INTERNAL_TRACE_EVENT_UID(category_group_enabled), name,     \
+          trace_event_trace_id.scope(), trace_event_trace_id.raw_id(),       \
+          node::tracing::kNoId, trace_event_flags, timestamp, ##__VA_ARGS__);\
+    }                                                                        \
+  } while (0)
 
 // Enter and leave a context based on the current scope.
 #define INTERNAL_TRACE_EVENT_SCOPED_CONTEXT(category_group, name, context) \

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