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,53 @@ 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);
+  }
+}
+
+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.
+  if (is_precise() && !IsHandleClosing()) {
+    uv_close(reinterpret_cast<uv_handle_t*>(&prepare_), 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->TraceHistogram();
 }
 
-bool ELDHistogram::RecordDelta() {
+void ELDHistogram::PrepareCallback(uv_prepare_t* handle) {
+  ELDHistogram* histogram = ContainerOf(&ELDHistogram::prepare_, handle);
+  histogram->RecordDelta();
+  histogram->TraceHistogram();
+}
+
+void ELDHistogram::RecordDelta() {
   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 +549,35 @@ bool ELDHistogram::RecordDelta() {
     }
   }
   prev_ = time;
-  return ret;
 }
 
 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()) {
+    CHECK_EQ(uv_prepare_start(&prepare_, PrepareCallback), 0);
+    uv_unref(reinterpret_cast<uv_handle_t*>(&prepare_));
+  } 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);
+  } else {
+    CHECK_EQ(uv_timer_stop(&timer_), 0);
+  }
   return true;
 }
 

src/node_perf.h

@@ -153,7 +153,8 @@ class ELDHistogram : public HandleWrap, public Histogram {
                Local<Object> wrap,
                int32_t resolution);
 
-  bool RecordDelta();
+  void RecordDelta();
+  void TraceHistogram();
   bool Enable();
   bool Disable();
   void ResetState() {
@@ -163,6 +164,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 +175,18 @@ class ELDHistogram : public HandleWrap, public Histogram {
 
  private:
   static void DelayIntervalCallback(uv_timer_t* req);
+  static void PrepareCallback(uv_prepare_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_;
 };
 
 }  // namespace performance

test/sequential/test-performance-eventloopdelay-reporting.js

@@ -0,0 +1,63 @@
+// Flags: --expose-internals
+'use strict';
+
+const common = require('../common');
+const assert = require('assert');
+const net = require('net');
+const {
+  monitorEventLoopDelay
+} = require('perf_hooks');
+const { sleep } = require('internal/util');
+
+const ASYNC_SCHEDULERS = [
+  (cb) => setTimeout(cb, common.platformTimeout(10)),
+  (cb) => {
+    const server = net.createServer(common.mustCall((s) => {
+      s.destroy();
+      server.close();
+
+      cb();
+    }));
+    server.listen(0, () => {
+      const { port } = server.address();
+      net.connect(port, common.mustCall(() => {}));
+    });
+  },
+];
+
+async function testSingle(resolution, callback) {
+  const histogram = monitorEventLoopDelay({ resolution });
+  histogram.enable();
+
+  for (const schedule of ASYNC_SCHEDULERS) {
+    histogram.reset();
+
+    const msSleep = common.platformTimeout(100);
+
+    await new Promise((resolve, reject) => {
+      schedule(() => {
+        sleep(msSleep);
+        resolve();
+      });
+    });
+
+    // Let the new event loop tick start
+    await new Promise((resolve, reject) => setTimeout(resolve, 10));
+
+    // Convert sleep time to nanoseconds
+    const nsSleep = msSleep * 1e6;
+
+    // We are generous
+    assert(histogram.max >= 0.75 * nsSleep,
+           `${histogram.max} must be greater or equal to ${0.75 * nsSleep}`);
+  }
+
+  histogram.disable();
+}
+
+async function test() {
+  await testSingle(0);
+  await testSingle(1);
+}
+
+test();

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() {