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>

5 files changed, 38 insertions, 28 deletions

diff --git a/src/env.cc b/src/env.cc
index 3d1e5d3ac1..c876103972 100644
--- a/src/env.cc
+++ b/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;
diff --git a/src/node.cc b/src/node.cc
index 4833ef0fd1..e7dd666934 100644
--- a/src/node.cc
+++ b/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);
diff --git a/src/node_perf.cc b/src/node_perf.cc
index 8260d78c32..8b476890e1 100644
--- a/src/node_perf.cc
+++ b/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);
 }
 
 
diff --git a/src/node_perf.h b/src/node_perf.h
index 0db99acd03..703ef81ce4 100644
--- a/src/node_perf.h
+++ b/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,
diff --git a/src/node_perf_common.h b/src/node_perf_common.h
index 7ff57359ba..9754e1e66f 100644
--- a/src/node_perf_common.h
+++ b/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