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: #18789 Reviewed-By: Ali Ijaz Sheikh <ofrobots@google.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com>
nodejs · Feb 14, 2018 · 9e509b622bbdc14b7153d006f57043f268017138 · 9e509b6
1 parent aca8e76
commit 9e509b622bbdc14b7153d006f57043f268017138
Unified Split

Showing with 131 additions and 11 deletions.

+2 −2 doc/api/perf_hooks.md

+16 −2 doc/api/tracing.md

+16 −4 src/node_perf.cc

+1 −0 src/node_perf.h

+14 −3 src/tracing/trace_event.h

+82 −0 test/parallel/test-trace-events-perf.js
diff --git a/doc/api/perf_hooks.md b/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'`,
-`'measure'`, `'gc'`, or `'function'`.
+The type of the performance entry. Currently it may be one of: `'node'`,
+`'mark'`, `'measure'`, `'gc'`, or `'function'`.

 ### performanceEntry.kind
 <!-- YAML
diff --git a/doc/api/tracing.md b/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
-enabled.
+names.
+
+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
diff --git a/src/node_perf.cc b/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
-  // record a trace event also.
+  TRACE_EVENT_COPY_MARK_WITH_TIMESTAMP(
+      "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
-  // record a trace event also.
+  TRACE_EVENT_COPY_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
+      "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,22 +271,32 @@ 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;
    }
    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;
diff --git a/src/node_perf.h b/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"
diff --git a/src/tracing/trace_event.h b/src/tracing/trace_event.h
@@ -244,9 +244,20 @@ enum CategoryGroupEnabledFlags {

 // Adds a trace event with a given id, thread_id, and timestamp. Not
 // Implemented.
-#define INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMP(            \
-    phase, category_group, name, id, thread_id, timestamp, flags, ...) \
-  UNIMPLEMENTED()
+#define INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMP(                  \
+    phase, category_group, name, id, thread_id, timestamp, flags, ...)       \
+  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) \
diff --git a/test/parallel/test-trace-events-perf.js 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');
+        }
+      });
+    }));
+  }));
+}