perf_hooks: precise mode for monitorEventLoopDelay

doc/api/perf_hooks.md

@@ -432,21 +432,34 @@ is equal to `type`.
 ## `perf_hooks.monitorEventLoopDelay([options])`
 <!-- YAML
 added: v11.10.0
+changes:
+  - version: REPLACEME
+    pr-url: https://github.com/nodejs/node/pull/32018
+    description: Introduce precise mode (`resolution` equal to `0`). Change
+      the default `resolution` to `0`.
 -->
 
 * `options` {Object}
-  * `resolution` {number} The sampling rate in milliseconds. Must be greater
-    than zero. **Default:** `10`.
+  * `resolution` {number} Optional sampling rate in milliseconds. Must be
+    greater or equal to zero. **Default:** `0`.
 * Returns: {Histogram}
 
 Creates a `Histogram` object that samples and reports the event loop delay
 over time. The delays will be reported in nanoseconds.
 
-Using a timer to detect approximate event loop delay works because the
-execution of timers is tied specifically to the lifecycle of the libuv
-event loop. That is, a delay in the loop will cause a delay in the execution
-of the timer, and those delays are specifically what this API is intended to
-detect.
+When `resolution` is zero a precise time difference between IO poll end and IO
+poll start is entered into the histogram on every event-loop iteration. During
+standby (i.e., no event-loop activity) - no data is added to the histogram, as
+would be expected.
+
+When `resolution` is non-zero a timer is used to detect approximate event loop
+delay. This works because the execution of timers is tied specifically to the
+lifecycle of the libuv event loop. That is, a delay in the loop will cause a
+delay in the execution of the timer, and those delays are specifically what this
+API is intended to detect. Timer-based monitoring happens continuously and adds
+delay statistics to the histogram even during standby when the Node.js would not
+otherwise be consuming CPU. Since this approach just checks the loop state
+periodically, it can easily miss loops that had excessive delays.
 
 ```js
 const { monitorEventLoopDelay } = require('perf_hooks');

lib/perf_hooks.js

@@ -604,12 +604,12 @@ function monitorEventLoopDelay(options = {}) {
   if (typeof options !== 'object' || options === null) {
     throw new ERR_INVALID_ARG_TYPE('options', 'Object', options);
   }
-  const { resolution = 10 } = options;
+  const { resolution = 0 } = options;
   if (typeof resolution !== 'number') {
     throw new ERR_INVALID_ARG_TYPE('options.resolution',
                                    'number', resolution);
   }
-  if (resolution <= 0 || !NumberIsSafeInteger(resolution)) {
+  if (resolution < 0 || !NumberIsSafeInteger(resolution)) {
     throw new ERR_INVALID_OPT_VALUE.RangeError('resolution', resolution);
   }
   return new ELDHistogram(new _ELDHistogram(resolution));

src/node_perf.cc

@@ -474,7 +474,7 @@ static void ELDHistogramNew(const FunctionCallbackInfo<Value>& args) {
   Environment* env = Environment::GetCurrent(args);
   CHECK(args.IsConstructCall());
   int32_t resolution = args[0]->IntegerValue(env->context()).FromJust();
-  CHECK_GT(resolution, 0);
+  CHECK_GE(resolution, 0);
   new ELDHistogram(env, args.This(), resolution);
 }
 }  // namespace
@@ -489,29 +489,61 @@ ELDHistogram::ELDHistogram(
                           Histogram(1, 3.6e12),
                           resolution_(resolution) {
   MakeWeak();
-  uv_timer_init(env->event_loop(), &timer_);
+
+  // Since we pass `timer_` to `HandleWrap` constructor - we have to
+  // initialize it here. It is equally important to have it initialized for
+  // correct operation of `Close()` below.
+  CHECK_EQ(uv_timer_init(env->event_loop(), &timer_), 0);
+
+  if (is_precise()) {
+    CHECK_EQ(uv_prepare_init(env->event_loop(), &prepare_), 0);
+    CHECK_EQ(uv_check_init(env->event_loop(), &check_), 0);
+  }
+}
+
+void ELDHistogram::Close(Local<Value> close_callback) {
+  // HandleWrap::Close will call `uv_close()` on `timer_` and
+  // deallocate `ELDHistogram` in `HandleWrap::OnClose`.
+  // Therefore, it is safe to call `uv_close` with `nullptr` here since
+  // both `prepare_` and `check_`.
+  if (is_precise() && !IsHandleClosing()) {
+    uv_close(reinterpret_cast<uv_handle_t*>(&prepare_), nullptr);
+    uv_close(reinterpret_cast<uv_handle_t*>(&check_), nullptr);
+  }
+
+  HandleWrap::Close(close_callback);
+}
+
+void ELDHistogram::TraceHistogram() {
+  TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop), "min", Min());
+  TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop), "max", Max());
+  TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop), "mean", Mean());
+  TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop), "stddev", Stddev());
 }
 
 void ELDHistogram::DelayIntervalCallback(uv_timer_t* req) {
   ELDHistogram* histogram = ContainerOf(&ELDHistogram::timer_, req);
-  histogram->RecordDelta();
-  TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop),
-                 "min", histogram->Min());
-  TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop),
-                 "max", histogram->Max());
-  TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop),
-                 "mean", histogram->Mean());
-  TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop),
-                 "stddev", histogram->Stddev());
+  histogram->RecordCoarseDelta();
+  histogram->TraceHistogram();
 }
 
-bool ELDHistogram::RecordDelta() {
+void ELDHistogram::CheckCallback(uv_check_t* handle) {
+  ELDHistogram* histogram = ContainerOf(&ELDHistogram::check_, handle);
+  histogram->RecordPreciseDelayStart();
+}
+
+void ELDHistogram::PrepareCallback(uv_prepare_t* handle) {
+  ELDHistogram* histogram = ContainerOf(&ELDHistogram::prepare_, handle);
+  histogram->RecordPreciseDelayStop();
+  histogram->TraceHistogram();
+}
+
+void ELDHistogram::RecordCoarseDelta() {
   uint64_t time = uv_hrtime();
-  bool ret = true;
   if (prev_ > 0) {
     int64_t delta = time - prev_;
     if (delta > 0) {
-      ret = Record(delta);
+      bool ret = Record(delta);
       TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop),
                      "delay", delta);
       if (!ret) {
@@ -525,25 +557,76 @@ bool ELDHistogram::RecordDelta() {
     }
   }
   prev_ = time;
-  return ret;
+}
+
+void ELDHistogram::RecordPreciseDelayStart() {
+  prev_ = uv_hrtime();
+}
+
+void ELDHistogram::RecordPreciseDelayStop() {
+  if (prev_ == 0) {
+    return;
+  }
+
+  uint64_t time = uv_hrtime();
+  int64_t delta = time - prev_;
+  if (delta <= 0) {
+    return;
+  }
+  bool ret = Record(delta);
+  TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop),
+                 "delay", delta);
+  if (ret) {
+    return;
+  }
+  if (exceeds_ < 0xFFFFFFFF) {
+    exceeds_++;
+  }
+  ProcessEmitWarning(
+      env(),
+      "Event loop delay exceeded 1 hour: %" PRId64 " nanoseconds",
+      delta);
 }
 
 bool ELDHistogram::Enable() {
   if (enabled_ || IsHandleClosing()) return false;
   enabled_ = true;
   prev_ = 0;
-  uv_timer_start(&timer_,
-                 DelayIntervalCallback,
-                 resolution_,
-                 resolution_);
-  uv_unref(reinterpret_cast<uv_handle_t*>(&timer_));
+
+  if (is_precise()) {
+    // `uv_prepare_start`/`uv_check_start` prepend the handles to the queue.
+    // Newly started handles will have their callbacks invoked **before** the
+    // old handles' callbacks.
+    //
+    // This is important because of `immediate_check_handle` in `src/env.cc`.
+    // `immediate_check_handle` is used for invoking user callbacks queued with
+    // `setImmediate()` API call. `ELDHistogram` has to record the delay
+    // induced by `setImmediate()` callbacks too so the order of handles is
+    // important.
+    CHECK_EQ(uv_prepare_start(&prepare_, PrepareCallback), 0);
+    CHECK_EQ(uv_check_start(&check_, CheckCallback), 0);
+    uv_unref(reinterpret_cast<uv_handle_t*>(&prepare_));
+    uv_unref(reinterpret_cast<uv_handle_t*>(&check_));
+  } else {
+    CHECK_EQ(uv_timer_start(&timer_,
+                            DelayIntervalCallback,
+                            resolution_,
+                            resolution_),
+        0);
+    uv_unref(reinterpret_cast<uv_handle_t*>(&timer_));
+  }
   return true;
 }
 
 bool ELDHistogram::Disable() {
   if (!enabled_ || IsHandleClosing()) return false;
   enabled_ = false;
-  uv_timer_stop(&timer_);
+  if (is_precise()) {
+    CHECK_EQ(uv_prepare_stop(&prepare_), 0);
+    CHECK_EQ(uv_check_stop(&check_), 0);
+  } else {
+    CHECK_EQ(uv_timer_stop(&timer_), 0);
+  }
   return true;
 }
 

src/node_perf.h

@@ -153,7 +153,10 @@ class ELDHistogram : public HandleWrap, public Histogram {
                Local<Object> wrap,
                int32_t resolution);
 
-  bool RecordDelta();
+  void RecordCoarseDelta();
+  void RecordPreciseDelayStart();
+  void RecordPreciseDelayStop();
+  void TraceHistogram();
   bool Enable();
   bool Disable();
   void ResetState() {
@@ -163,6 +166,8 @@ class ELDHistogram : public HandleWrap, public Histogram {
   }
   int64_t Exceeds() { return exceeds_; }
 
+  void Close(Local<Value> close_callback = Local<Value>()) override;
+
   void MemoryInfo(MemoryTracker* tracker) const override {
     tracker->TrackFieldWithSize("histogram", GetMemorySize());
   }
@@ -172,12 +177,20 @@ class ELDHistogram : public HandleWrap, public Histogram {
 
  private:
   static void DelayIntervalCallback(uv_timer_t* req);
+  static void PrepareCallback(uv_prepare_t* handle);
+  static void CheckCallback(uv_check_t* handle);
+
+  inline bool is_precise() const {
+    return resolution_ == 0;
+  }
 
   bool enabled_ = false;
   int32_t resolution_ = 0;
   int64_t exceeds_ = 0;
   uint64_t prev_ = 0;
   uv_timer_t timer_;
+  uv_prepare_t prepare_;
+  uv_check_t check_;
 };
 
 }  // namespace performance

test/sequential/test-performance-eventloopdelay.js

@@ -39,7 +39,7 @@ const { sleep } = require('internal/util');
     );
   });
 
-  [-1, 0, Infinity].forEach((i) => {
+  [-1, Infinity].forEach((i) => {
     assert.throws(
       () => monitorEventLoopDelay({ resolution: i }),
       {
@@ -50,8 +50,8 @@ const { sleep } = require('internal/util');
   });
 }
 
-{
-  const histogram = monitorEventLoopDelay({ resolution: 1 });
+for (const resolution of [ 0, 1 ]) {
+  const histogram = monitorEventLoopDelay({ resolution });
   histogram.enable();
   let m = 5;
   function spinAWhile() {