perf_hooks,trace_events: emit perf milestone trace events

Emit the perf_hooks node timing milestones as trace events.

PR-URL: https://github.com/nodejs/node/pull/19175
Reviewed-By: Anna Henningsen <anna@addaleax.net>

doc/api/tracing.md

@@ -16,6 +16,7 @@ The available categories are:
 
 * `node`
 * `node.async_hooks` - Enables capture of detailed async_hooks trace data.
+* `node.bootstrap` - Enables capture of Node.js bootstrap milestones.
 * `node.perf` - Enables capture of [Performance API] measurements.
   * `node.perf.usertiming` - Enables capture of only Performance API User Timing
     measures and marks.

src/env.cc

@@ -115,15 +115,14 @@ Environment::Environment(IsolateData* isolate_data,
 
   destroy_async_id_list_.reserve(512);
   performance_state_.reset(new performance::performance_state(isolate()));
-  performance_state_->milestones[
-      performance::NODE_PERFORMANCE_MILESTONE_ENVIRONMENT] =
-          PERFORMANCE_NOW();
-  performance_state_->milestones[
-    performance::NODE_PERFORMANCE_MILESTONE_NODE_START] =
-        performance::performance_node_start;
-  performance_state_->milestones[
-    performance::NODE_PERFORMANCE_MILESTONE_V8_START] =
-        performance::performance_v8_start;
+  performance_state_->Mark(
+      performance::NODE_PERFORMANCE_MILESTONE_ENVIRONMENT);
+  performance_state_->Mark(
+      performance::NODE_PERFORMANCE_MILESTONE_NODE_START,
+      performance::performance_node_start);
+  performance_state_->Mark(
+      performance::NODE_PERFORMANCE_MILESTONE_V8_START,
+      performance::performance_v8_start);
 
   // By default, always abort when --abort-on-uncaught-exception was passed.
   should_abort_on_uncaught_toggle_[0] = 1;

src/node.cc

@@ -4474,7 +4474,8 @@ inline int Start(Isolate* isolate, IsolateData* isolate_data,
   {
     SealHandleScope seal(isolate);
     bool more;
-    PERFORMANCE_MARK(&env, LOOP_START);
+    env.performance_state()->Mark(
+        node::performance::NODE_PERFORMANCE_MILESTONE_LOOP_START);
     do {
       uv_run(env.event_loop(), UV_RUN_DEFAULT);
 
@@ -4490,7 +4491,8 @@ inline int Start(Isolate* isolate, IsolateData* isolate_data,
       // event, or after running some callbacks.
       more = uv_loop_alive(env.event_loop());
     } while (more == true);
-    PERFORMANCE_MARK(&env, LOOP_EXIT);
+    env.performance_state()->Mark(
+        node::performance::NODE_PERFORMANCE_MILESTONE_LOOP_EXIT);
   }
 
   env.set_trace_sync_io(false);

src/node_perf.cc

@@ -40,6 +40,15 @@ uint64_t performance_v8_start;
 uint64_t performance_last_gc_start_mark_ = 0;
 v8::GCType performance_last_gc_type_ = v8::GCType::kGCTypeAll;
 
+void performance_state::Mark(enum PerformanceMilestone milestone,
+                             uint64_t ts) {
+  this->milestones[milestone] = ts;
+  TRACE_EVENT_INSTANT_WITH_TIMESTAMP0(
+      TRACING_CATEGORY_NODE1(bootstrap),
+      GetPerformanceMilestoneName(milestone),
+      TRACE_EVENT_SCOPE_THREAD, ts);
+}
+
 double GetCurrentTimeInMicroseconds() {
 #ifdef _WIN32
 // The difference between the Unix Epoch and the Windows Epoch in 100-ns ticks.
@@ -200,14 +209,11 @@ void Measure(const FunctionCallbackInfo<Value>& args) {
 void MarkMilestone(const FunctionCallbackInfo<Value>& args) {
   Environment* env = Environment::GetCurrent(args);
   Local<Context> context = env->context();
-  AliasedBuffer<double, v8::Float64Array>& milestones =
-      env->performance_state()->milestones;
   PerformanceMilestone milestone =
       static_cast<PerformanceMilestone>(
           args[0]->Int32Value(context).ToChecked());
-  if (milestone != NODE_PERFORMANCE_MILESTONE_INVALID) {
-    milestones[milestone] = PERFORMANCE_NOW();
-  }
+  if (milestone != NODE_PERFORMANCE_MILESTONE_INVALID)
+    env->performance_state()->Mark(milestone);
 }
 
 

src/node_perf.h

@@ -27,6 +27,18 @@ extern const uint64_t timeOrigin;
 
 double GetCurrentTimeInMicroseconds();
 
+static inline const char* GetPerformanceMilestoneName(
+    enum PerformanceMilestone milestone) {
+  switch (milestone) {
+#define V(name, label) case NODE_PERFORMANCE_MILESTONE_##name: return label;
+  NODE_PERFORMANCE_MILESTONES(V)
+#undef V
+    default:
+      UNREACHABLE();
+      return 0;
+  }
+}
+
 static inline PerformanceMilestone ToPerformanceMilestoneEnum(const char* str) {
 #define V(name, label)                                                        \
   if (strcmp(str, label) == 0) return NODE_PERFORMANCE_MILESTONE_##name;
@@ -44,12 +56,6 @@ static inline PerformanceEntryType ToPerformanceEntryTypeEnum(
   return NODE_PERFORMANCE_ENTRY_TYPE_INVALID;
 }
 
-NODE_EXTERN inline void MarkPerformanceMilestone(
-    Environment* env,
-    PerformanceMilestone milestone) {
-  env->performance_state()->milestones[milestone] = PERFORMANCE_NOW();
-}
-
 class PerformanceEntry {
  public:
   static void Notify(Environment* env,

src/node_perf_common.h

@@ -56,12 +56,6 @@ enum PerformanceEntryType {
   NODE_PERFORMANCE_ENTRY_TYPE_INVALID
 };
 
-#define PERFORMANCE_MARK(env, n)                                              \
-  do {                                                                        \
-    node::performance::MarkPerformanceMilestone(env,                          \
-                         node::performance::NODE_PERFORMANCE_MILESTONE_##n);  \
-  } while (0);
-
 class performance_state {
  public:
   explicit performance_state(v8::Isolate* isolate) :
@@ -86,6 +80,9 @@ class performance_state {
   AliasedBuffer<double, v8::Float64Array> milestones;
   AliasedBuffer<uint32_t, v8::Uint32Array> observers;
 
+  void Mark(enum PerformanceMilestone milestone,
+            uint64_t ts = PERFORMANCE_NOW());
+
  private:
   struct performance_state_internal {
     // doubles first so that they are always sizeof(double)-aligned

test/parallel/test-trace-events-bootstrap.js

@@ -0,0 +1,53 @@
+'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');
+
+const names = [
+  'environment',
+  'nodeStart',
+  'v8Start',
+  'loopStart',
+  'loopExit',
+  'bootstrapComplete',
+  'thirdPartyMainStart',
+  'thirdPartyMainEnd',
+  'clusterSetupStart',
+  'clusterSetupEnd',
+  'moduleLoadStart',
+  'moduleLoadEnd',
+  'preloadModulesLoadStart',
+  'preloadModulesLoadEnd'
+];
+
+if (process.argv[2] === 'child') {
+  1 + 1;
+} else {
+  tmpdir.refresh();
+  process.chdir(tmpdir.path);
+
+  const proc = cp.fork(__filename,
+                       [ 'child' ], {
+                         execArgv: [
+                           '--trace-events-enabled',
+                           '--trace-event-categories',
+                           'node.bootstrap'
+                         ]
+                       });
+
+  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;
+      traces.forEach((trace) => {
+        assert.strictEqual(trace.pid, proc.pid);
+        assert(names.includes(trace.name));
+      });
+    }));
+  }));
+}