perf_hooks: complete overhaul of the implementation

* Update the user timing implementation to conform to
  User Timing Level 3.
* Reimplement user timing and timerify with pure JavaScript
  implementations
* Simplify the C++ implementation for gc and http2 perf
* Runtime deprecate additional perf entry properties
  in favor of the standard detail argument
* Disable the `buffered` option on PerformanceObserver,
  all entries are queued and dispatched on setImmediate.
  Only entries with active observers are buffered.
* This does remove the user timing and timerify
  trace events. Because the trace_events are still
  considered experimental, those can be removed without
  a deprecation cycle. They are removed to improve
  performance and reduce complexity.

Old: `perf_hooks/usertiming.js n=100000: 92,378.01249733355`
New: perf_hooks/usertiming.js n=100000: 270,393.5280638482`

PR-URL: https://github.com/nodejs/node/pull/37136
Refs: https://github.com/nodejs/diagnostics/issues/464
Reviewed-By: Antoine du Hamel <duhamelantoine1995@gmail.com>
Reviewed-By: Matteo Collina <matteo.collina@gmail.com>
Reviewed-By: Michaël Zasso <targos@protonmail.com>

1 files changed, 55 insertions, 273 deletions

diff --git a/src/node_perf.cc b/src/node_perf.cc
index 73fc31394b..2d6341e011 100644
--- a/src/node_perf.cc
+++ b/src/node_perf.cc
@@ -1,4 +1,5 @@
 #include "aliased_buffer.h"
+#include "env-inl.h"
 #include "histogram-inl.h"
 #include "memory_tracker-inl.h"
 #include "node_internals.h"
@@ -19,7 +20,6 @@ using v8::FunctionCallbackInfo;
 using v8::FunctionTemplate;
 using v8::GCCallbackFlags;
 using v8::GCType;
-using v8::HandleScope;
 using v8::Int32;
 using v8::Integer;
 using v8::Isolate;
@@ -87,8 +87,7 @@ std::ostream& operator<<(std::ostream& o,
   return o;
 }
 
-void PerformanceState::Mark(enum PerformanceMilestone milestone,
-                             uint64_t ts) {
+void PerformanceState::Mark(PerformanceMilestone milestone, uint64_t ts) {
   this->milestones[milestone] = static_cast<double>(ts);
   TRACE_EVENT_INSTANT_WITH_TIMESTAMP0(
       TRACING_CATEGORY_NODE1(bootstrap),
@@ -96,234 +95,83 @@ void PerformanceState::Mark(enum PerformanceMilestone milestone,
       TRACE_EVENT_SCOPE_THREAD, ts / 1000);
 }
 
-// Initialize the performance entry object properties
-inline void InitObject(const PerformanceEntry& entry, Local<Object> obj) {
-  Environment* env = entry.env();
-  Isolate* isolate = env->isolate();
-  Local<Context> context = env->context();
-  PropertyAttribute attr =
-      static_cast<PropertyAttribute>(ReadOnly | DontDelete);
-  obj->DefineOwnProperty(context,
-                         env->name_string(),
-                         String::NewFromUtf8(isolate,
-                                             entry.name().c_str())
-                             .ToLocalChecked(),
-                         attr)
-      .Check();
-  obj->DefineOwnProperty(context,
-                         env->entry_type_string(),
-                         String::NewFromUtf8(isolate,
-                                             entry.type().c_str())
-                             .ToLocalChecked(),
-                         attr)
-      .Check();
-  obj->DefineOwnProperty(context,
-                         env->start_time_string(),
-                         Number::New(isolate, entry.startTime()),
-                         attr).Check();
-  obj->DefineOwnProperty(context,
-                         env->duration_string(),
-                         Number::New(isolate, entry.duration()),
-                         attr).Check();
-}
-
-// Create a new PerformanceEntry object
-MaybeLocal<Object> PerformanceEntry::ToObject() const {
-  Local<Object> obj;
-  if (!env_->performance_entry_template()
-           ->NewInstance(env_->context())
-           .ToLocal(&obj)) {
-    return MaybeLocal<Object>();
-  }
-  InitObject(*this, obj);
-  return obj;
-}
-
-// Allow creating a PerformanceEntry object from JavaScript
-void PerformanceEntry::New(const FunctionCallbackInfo<Value>& args) {
-  Environment* env = Environment::GetCurrent(args);
-  Isolate* isolate = env->isolate();
-  Utf8Value name(isolate, args[0]);
-  Utf8Value type(isolate, args[1]);
-  uint64_t now = PERFORMANCE_NOW();
-  PerformanceEntry entry(env, *name, *type, now, now);
-  Local<Object> obj = args.This();
-  InitObject(entry, obj);
-  PerformanceEntry::Notify(env, entry.kind(), obj);
-}
-
-// Pass the PerformanceEntry object to the PerformanceObservers
-void PerformanceEntry::Notify(Environment* env,
-                              PerformanceEntryType type,
-                              Local<Value> object) {
-  Context::Scope scope(env->context());
-  AliasedUint32Array& observers = env->performance_state()->observers;
-  if (!env->performance_entry_callback().IsEmpty() &&
-      type != NODE_PERFORMANCE_ENTRY_TYPE_INVALID && observers[type]) {
-    node::MakeSyncCallback(env->isolate(),
-                           object.As<Object>(),
-                           env->performance_entry_callback(),
-                           1, &object);
-  }
-}
-
-// Create a User Timing Mark
-void Mark(const FunctionCallbackInfo<Value>& args) {
-  Environment* env = Environment::GetCurrent(args);
-  HandleScope scope(env->isolate());
-  Utf8Value name(env->isolate(), args[0]);
-  uint64_t now = PERFORMANCE_NOW();
-  auto marks = env->performance_marks();
-  (*marks)[*name] = now;
-
-  TRACE_EVENT_COPY_MARK_WITH_TIMESTAMP(
-      TRACING_CATEGORY_NODE2(perf, usertiming),
-      *name, now / 1000);
-
-  PerformanceEntry entry(env, *name, "mark", now, now);
-  Local<Object> obj;
-  if (!entry.ToObject().ToLocal(&obj)) return;
-  PerformanceEntry::Notify(env, entry.kind(), obj);
-  args.GetReturnValue().Set(obj);
-}
-
-void ClearMark(const FunctionCallbackInfo<Value>& args) {
-  Environment* env = Environment::GetCurrent(args);
-  auto marks = env->performance_marks();
-
-  if (args.Length() == 0) {
-    marks->clear();
-  } else {
-    Utf8Value name(env->isolate(), args[0]);
-    marks->erase(*name);
-  }
-}
-
-inline uint64_t GetPerformanceMark(Environment* env, const std::string& name) {
-  auto marks = env->performance_marks();
-  auto res = marks->find(name);
-  return res != marks->end() ? res->second : 0;
-}
-
-// Create a User Timing Measure. A Measure is a PerformanceEntry that
-// measures the duration between two distinct user timing marks
-void Measure(const FunctionCallbackInfo<Value>& args) {
-  Environment* env = Environment::GetCurrent(args);
-  HandleScope scope(env->isolate());
-  Utf8Value name(env->isolate(), args[0]);
-  Utf8Value startMark(env->isolate(), args[1]);
-
-  AliasedFloat64Array& milestones = env->performance_state()->milestones;
-
-  uint64_t startTimestamp = timeOrigin;
-  uint64_t start = GetPerformanceMark(env, *startMark);
-  if (start != 0) {
-    startTimestamp = start;
-  } else {
-    PerformanceMilestone milestone = ToPerformanceMilestoneEnum(*startMark);
-    if (milestone != NODE_PERFORMANCE_MILESTONE_INVALID)
-      startTimestamp = milestones[milestone];
-  }
-
-  uint64_t endTimestamp = 0;
-  if (args[2]->IsUndefined()) {
-    endTimestamp = PERFORMANCE_NOW();
-  } else {
-    Utf8Value endMark(env->isolate(), args[2]);
-    endTimestamp = GetPerformanceMark(env, *endMark);
-    if (endTimestamp == 0) {
-      PerformanceMilestone milestone = ToPerformanceMilestoneEnum(*endMark);
-      if (milestone != NODE_PERFORMANCE_MILESTONE_INVALID)
-        endTimestamp = milestones[milestone];
-    }
-  }
-
-  if (endTimestamp < startTimestamp)
-    endTimestamp = startTimestamp;
-
-  TRACE_EVENT_COPY_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
-      TRACING_CATEGORY_NODE2(perf, usertiming),
-      *name, *name, startTimestamp / 1000);
-  TRACE_EVENT_COPY_NESTABLE_ASYNC_END_WITH_TIMESTAMP0(
-      TRACING_CATEGORY_NODE2(perf, usertiming),
-      *name, *name, endTimestamp / 1000);
-
-  PerformanceEntry entry(env, *name, "measure", startTimestamp, endTimestamp);
-  Local<Object> obj;
-  if (!entry.ToObject().ToLocal(&obj)) return;
-  PerformanceEntry::Notify(env, entry.kind(), obj);
-  args.GetReturnValue().Set(obj);
-}
-
 // Allows specific Node.js lifecycle milestones to be set from JavaScript
 void MarkMilestone(const FunctionCallbackInfo<Value>& args) {
   Environment* env = Environment::GetCurrent(args);
-  Local<Context> context = env->context();
   PerformanceMilestone milestone =
-      static_cast<PerformanceMilestone>(
-          args[0]->Int32Value(context).ToChecked());
+      static_cast<PerformanceMilestone>(args[0].As<Int32>()->Value());
   if (milestone != NODE_PERFORMANCE_MILESTONE_INVALID)
     env->performance_state()->Mark(milestone);
 }
 
-
 void SetupPerformanceObservers(const FunctionCallbackInfo<Value>& args) {
   Environment* env = Environment::GetCurrent(args);
   CHECK(args[0]->IsFunction());
   env->set_performance_entry_callback(args[0].As<Function>());
 }
 
-// Creates a GC Performance Entry and passes it to observers
-void PerformanceGCCallback(Environment* env,
-                           std::unique_ptr<GCPerformanceEntry> entry) {
-  HandleScope scope(env->isolate());
-  Local<Context> context = env->context();
-
-  AliasedUint32Array& observers = env->performance_state()->observers;
-  if (observers[NODE_PERFORMANCE_ENTRY_TYPE_GC]) {
-    Local<Object> obj;
-    if (!entry->ToObject().ToLocal(&obj)) return;
-    PropertyAttribute attr =
-        static_cast<PropertyAttribute>(ReadOnly | DontDelete);
-    obj->DefineOwnProperty(context,
-                           env->kind_string(),
-                           Integer::New(env->isolate(), entry->gckind()),
-                           attr).Check();
-    obj->DefineOwnProperty(context,
-                           env->flags_string(),
-                           Integer::New(env->isolate(), entry->gcflags()),
-                           attr).Check();
-    PerformanceEntry::Notify(env, entry->kind(), obj);
-  }
-}
-
 // Marks the start of a GC cycle
-void MarkGarbageCollectionStart(Isolate* isolate,
-                                GCType type,
-                                GCCallbackFlags flags,
-                                void* data) {
+void MarkGarbageCollectionStart(
+    Isolate* isolate,
+    GCType type,
+    GCCallbackFlags flags,
+    void* data) {
   Environment* env = static_cast<Environment*>(data);
   env->performance_state()->performance_last_gc_start_mark = PERFORMANCE_NOW();
 }
 
+MaybeLocal<Object> GCPerformanceEntryTraits::GetDetails(
+    Environment* env,
+    const GCPerformanceEntry& entry) {
+  Local<Object> obj = Object::New(env->isolate());
+
+  if (!obj->Set(
+          env->context(),
+          env->kind_string(),
+          Integer::NewFromUnsigned(
+              env->isolate(),
+              entry.details.kind)).IsJust()) {
+    return MaybeLocal<Object>();
+  }
+
+  if (!obj->Set(
+          env->context(),
+          env->flags_string(),
+          Integer::NewFromUnsigned(
+              env->isolate(),
+              entry.details.flags)).IsJust()) {
+    return MaybeLocal<Object>();
+  }
+
+  return obj;
+}
+
 // Marks the end of a GC cycle
-void MarkGarbageCollectionEnd(Isolate* isolate,
-                              GCType type,
-                              GCCallbackFlags flags,
-                              void* data) {
+void MarkGarbageCollectionEnd(
+    Isolate* isolate,
+    GCType type,
+    GCCallbackFlags flags,
+    void* data) {
   Environment* env = static_cast<Environment*>(data);
   PerformanceState* state = env->performance_state();
   // If no one is listening to gc performance entries, do not create them.
-  if (!state->observers[NODE_PERFORMANCE_ENTRY_TYPE_GC])
+  if (LIKELY(!state->observers[NODE_PERFORMANCE_ENTRY_TYPE_GC]))
     return;
-  auto entry = std::make_unique<GCPerformanceEntry>(
-      env,
-      static_cast<PerformanceGCKind>(type),
-      static_cast<PerformanceGCFlags>(flags),
-      state->performance_last_gc_start_mark,
-      PERFORMANCE_NOW());
-  env->SetImmediate([entry = std::move(entry)](Environment* env) mutable {
-    PerformanceGCCallback(env, std::move(entry));
+
+  double start_time = state->performance_last_gc_start_mark / 1e6;
+  double duration = (PERFORMANCE_NOW() / 1e6) - start_time;
+
+  std::unique_ptr<GCPerformanceEntry> entry =
+      std::make_unique<GCPerformanceEntry>(
+          "gc",
+          start_time,
+          duration,
+          GCPerformanceEntry::Details(
+            static_cast<PerformanceGCKind>(type),
+            static_cast<PerformanceGCFlags>(flags)));
+
+  env->SetImmediate([entry = std::move(entry)](Environment* env) {
+    entry->Notify(env);
   }, CallbackFlags::kUnrefed);
 }
 
@@ -364,68 +212,6 @@ inline Local<Value> GetName(Local<Function> fn) {
   return val;
 }
 
-// Executes a wrapped Function and captures timing information, causing a
-// Function PerformanceEntry to be emitted to PerformanceObservers after
-// execution.
-void TimerFunctionCall(const FunctionCallbackInfo<Value>& args) {
-  Isolate* isolate = args.GetIsolate();
-  Local<Context> context = isolate->GetCurrentContext();
-  Environment* env = Environment::GetCurrent(context);
-  CHECK_NOT_NULL(env);
-  Local<Function> fn = args.Data().As<Function>();
-  size_t count = args.Length();
-  size_t idx;
-  SlicedArguments call_args(args);
-  Utf8Value name(isolate, GetName(fn));
-  bool is_construct_call = args.IsConstructCall();
-
-  uint64_t start = PERFORMANCE_NOW();
-  TRACE_EVENT_COPY_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
-      TRACING_CATEGORY_NODE2(perf, timerify),
-      *name, *name, start / 1000);
-  v8::MaybeLocal<Value> ret;
-
-  if (is_construct_call) {
-    ret = fn->NewInstance(context, call_args.length(), call_args.out())
-        .FromMaybe(Local<Object>());
-  } else {
-    ret = fn->Call(context, args.This(), call_args.length(), call_args.out());
-  }
-
-  uint64_t end = PERFORMANCE_NOW();
-  TRACE_EVENT_COPY_NESTABLE_ASYNC_END_WITH_TIMESTAMP0(
-      TRACING_CATEGORY_NODE2(perf, timerify),
-      *name, *name, end / 1000);
-
-  if (ret.IsEmpty())
-    return;
-  args.GetReturnValue().Set(ret.ToLocalChecked());
-
-  AliasedUint32Array& observers = env->performance_state()->observers;
-  if (!observers[NODE_PERFORMANCE_ENTRY_TYPE_FUNCTION])
-    return;
-
-  PerformanceEntry entry(env, *name, "function", start, end);
-  Local<Object> obj;
-  if (!entry.ToObject().ToLocal(&obj)) return;
-  for (idx = 0; idx < count; idx++)
-    obj->Set(context, idx, args[idx]).Check();
-  PerformanceEntry::Notify(env, entry.kind(), obj);
-}
-
-// Wraps a Function in a TimerFunctionCall
-void Timerify(const FunctionCallbackInfo<Value>& args) {
-  Environment* env = Environment::GetCurrent(args);
-  Local<Context> context = env->context();
-  CHECK(args[0]->IsFunction());
-  CHECK(args[1]->IsNumber());
-  Local<Function> fn = args[0].As<Function>();
-  int length = args[1]->IntegerValue(context).ToChecked();
-  Local<Function> wrap =
-      Function::New(context, TimerFunctionCall, fn, length).ToLocalChecked();
-  args.GetReturnValue().Set(wrap);
-}
-
 // Notify a custom PerformanceEntry to observers
 void Notify(const FunctionCallbackInfo<Value>& args) {
   Environment* env = Environment::GetCurrent(args);
@@ -512,12 +298,8 @@ void Initialize(Local<Object> target,
   target->Set(context, performanceEntryString, fn).Check();
   env->set_performance_entry_template(fn);
 
-  env->SetMethod(target, "clearMark", ClearMark);
-  env->SetMethod(target, "mark", Mark);
-  env->SetMethod(target, "measure", Measure);
   env->SetMethod(target, "markMilestone", MarkMilestone);
   env->SetMethod(target, "setupObservers", SetupPerformanceObservers);
-  env->SetMethod(target, "timerify", Timerify);
   env->SetMethod(target,
                  "installGarbageCollectionTracking",
                  InstallGarbageCollectionTracking);