perf_hooks: add idleTime and event loop util

Use uv_metrics_idle_time() to return a high resolution millisecond timer of the amount of time the event loop has been idle since it was initialized. Include performance.eventLoopUtilization() API to handle the math of calculating the idle and active times. This has been added to prevent accidental miscalculations of the event loop utilization. Such as not taking into consideration offsetting nodeTiming.loopStart or timing differences when being called from a Worker thread. PR-URL: #34938 Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Adrian Estrada <edsadr@gmail.com> Reviewed-By: Juan José Arboleda <soyjuanarbol@gmail.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: Stephen Belanger <admin@stephenbelanger.com> Reviewed-By: Gireesh Punathil <gpunathi@in.ibm.com> Reviewed-By: Gerhard Stöbich <deb2001-github@yahoo.de>
nodejs · Sep 22, 2020 · 2c409a285359faae58227da283a4c7e5cd9a2f0c · 2c409a2
1 parent b117467
commit 2c409a285359faae58227da283a4c7e5cd9a2f0c
diff --git a/benchmark/README.md b/benchmark/README.md
@@ -32,6 +32,7 @@ directory, see [the guide on benchmarks](../doc/guides/writing-and-running-bench
 | module          | Benchmarks for the `module` subsystem.                                                                           |
 | net             | Benchmarks for the `net` subsystem.                                                                              |
 | path            | Benchmarks for the `path` subsystem.                                                                             |
+| perf_hooks      | Benchmarks for the `perf_hooks` subsystem.                                                                       |
 | process         | Benchmarks for the `process` subsystem.                                                                          |
 | querystring     | Benchmarks for the `querystring` subsystem.                                                                      |
 | streams         | Benchmarks for the `streams` subsystem.                                                                          |

diff --git a/benchmark/perf_hooks/bench-eventlooputil.js b/benchmark/perf_hooks/bench-eventlooputil.js
@@ -0,0 +1,64 @@
+'use strict';
+
+const common = require('../common.js');
+const assert = require('assert').ok;
+const { performance } = require('perf_hooks');
+const { nodeTiming, eventLoopUtilization } = performance;
+
+const bench = common.createBenchmark(main, {
+  n: [1e6],
+  method: [
+    'idleTime',
+    'ELU_simple',
+    'ELU_passed',
+  ],
+});
+
+function main({ method, n }) {
+  switch (method) {
+    case 'idleTime':
+      benchIdleTime(n);
+      break;
+    case 'ELU_simple':
+      benchELUSimple(n);
+      break;
+    case 'ELU_passed':
+      benchELUPassed(n);
+      break;
+    default:
+      throw new Error(`Unsupported method ${method}`);
+  }
+}
+
+function benchIdleTime(n) {
+  bench.start();
+  for (let i = 0; i < n; i++)
+    nodeTiming.idleTime;
+  bench.end(n);
+}
+
+function benchELUSimple(n) {
+  // Need to put this in setImmediate or will always return 0.
+  setImmediate(() => {
+    const elu = eventLoopUtilization();
+    assert(elu.active + elu.idle > 0);
+
+    bench.start();
+    for (let i = 0; i < n; i++)
+      eventLoopUtilization();
+    bench.end(n);
+  });
+}
+
+function benchELUPassed(n) {
+  // Need to put this in setImmediate or will always return 0.
+  setImmediate(() => {
+    let elu = eventLoopUtilization();
+    assert(elu.active + elu.idle > 0);
+
+    bench.start();
+    for (let i = 0; i < n; i++)
+      elu = eventLoopUtilization(elu);
+    bench.end(n);
+  });
+}
diff --git a/doc/api/perf_hooks.md b/doc/api/perf_hooks.md
@@ -163,6 +163,62 @@ obs.observe({ entryTypes: ['function'] });
 wrapped();
 ```
 
+### `performance.eventLoopUtilization([util1][,util2])`
+<!-- YAML
+added: REPLACEME
+-->
+
+* `util1` {Object} The result of a previous call to `eventLoopUtilization()`
+* `util2` {Object} The result of a previous call to `eventLoopUtilization()`
+    prior to `util1`
+* Returns {Object}
+  * `idle` {number}
+  * `active` {number}
+  * `utilization` {number}
+
+The `eventLoopUtilization()` method returns an object that contains the
+cumulative duration of time the event loop has been both idle and active as a
+high resolution milliseconds timer. The `utilization` value is the calculated
+Event Loop Utilization (ELU). If bootstrapping has not yet finished, the
+properties have the value of 0.
+
+`util1` and `util2` are optional parameters.
+
+If `util1` is passed then the delta between the current call's `active` and
+`idle` times are calculated and returned (similar to [`process.hrtime()`][]).
+Likewise the adjusted `utilization` value is calculated.
+
+If `util1` and `util2` are both passed then the calculation adjustments are
+done between the two arguments. This is a convenience option because unlike
+[`process.hrtime()`][] additional work is done to calculate the ELU.
+
+ELU is similar to CPU utilization except that it is calculated using high
+precision wall-clock time. It represents the percentage of time the event loop
+has spent outside the event loop's event provider (e.g. `epoll_wait`). No other
+CPU idle time is taken into consideration. The following is an example of how
+a mostly idle process will have a high ELU.
+
+<!-- eslint-skip -->
+```js
+'use strict';
+const { eventLoopUtilization } = require('perf_hooks').performance;
+const { spawnSync } = require('child_process');
+
+setImmediate(() => {
+  const elu = eventLoopUtilization();
+  spawnSync('sleep', ['5']);
+  console.log(eventLoopUtilization(elu).utilization);
+});
+```
+
+While the CPU is mostly idle while running this script the value of
+`utilization` is 1. This is because the call to [`child_process.spawnSync()`][]
+blocks the event loop from proceeding.
+
+Passing in a user-defined object instead of the result of a previous call to
+`eventLoopUtilization()` will lead to undefined behavior. The return values
+are not guaranteed to reflect any correct state of the event loop.
+
 ## Class: `PerformanceEntry`
 <!-- YAML
 added: v8.5.0
@@ -326,6 +382,19 @@ added: v8.5.0
 The high resolution millisecond timestamp at which the V8 platform was
 initialized.
 
+### `performanceNodeTiming.idleTime`
+<!-- YAML
+added: REPLACEME
+-->
+
+* {number}
+
+The high resolution millisecond timestamp of the amount of time the event loop
+has been idle within the event loop's event provider (e.g. `epoll_wait`). This
+does not take CPU usage into consideration. If the event loop has not yet
+started (e.g., in the first tick of the main script), the property has the
+value of 0.
+
 ## Class: `perf_hooks.PerformanceObserver`
 
 ### `new PerformanceObserver(callback)`
@@ -682,6 +751,8 @@ require('some-module');
 ```
 
 [`'exit'`]: process.html#process_event_exit
+[`process.hrtime()`]: process.html#process_process_hrtime_time
+[`child_process.spawnSync()`]: #child_process_child_process_spawnsync_command_args_options
 [`timeOrigin`]: https://w3c.github.io/hr-time/#dom-performance-timeorigin
 [`window.performance`]: https://developer.mozilla.org/en-US/docs/Web/API/Window/performance
 [Async Hooks]: async_hooks.html

diff --git a/lib/perf_hooks.js b/lib/perf_hooks.js
@@ -25,7 +25,8 @@ const {
   timerify,
   constants,
   installGarbageCollectionTracking,
-  removeGarbageCollectionTracking
+  removeGarbageCollectionTracking,
+  loopIdleTime,
 } = internalBinding('performance');
 
 const {
@@ -205,6 +206,10 @@ class PerformanceNodeTiming extends PerformanceEntry {
     return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_BOOTSTRAP_COMPLETE);
   }
 
+  get idleTime() {
+    return loopIdleTime();
+  }
+
   [kInspect]() {
     return {
       name: 'node',
@@ -448,10 +453,37 @@ class Performance {
     return ret;
   }
 
+  eventLoopUtilization(util1, util2) {
+    const ls = nodeTiming.loopStart;
+
+    if (ls <= 0) {
+      return { idle: 0, active: 0, utilization: 0 };
+    }
+
+    if (util2) {
+      const idle = util1.idle - util2.idle;
+      const active = util1.active - util2.active;
+      return { idle, active, utilization: active / (idle + active) };
+    }
+
+    const idle = nodeTiming.idleTime;
+    const active = performance.now() - ls - idle;
+
+    if (!util1) {
+      return { idle, active, utilization: active / (idle + active) };
+    }
+
+    const idle_delta = idle - util1.idle;
+    const active_delta = active - util1.active;
+    const utilization = active_delta / (idle_delta + active_delta);
+    return { idle: idle_delta, active: active_delta, utilization };
+  }
+
   [kInspect]() {
     return {
       nodeTiming: this.nodeTiming,
-      timeOrigin: this.timeOrigin
+      timeOrigin: this.timeOrigin,
+      idleTime: this.idleTime,
     };
   }
 }

diff --git a/src/node.cc b/src/node.cc
@@ -985,6 +985,7 @@ int Start(int argc, char** argv) {
         indexes = NodeMainInstance::GetIsolateDataIndexes();
       }
     }
+    uv_loop_configure(uv_default_loop(), UV_METRICS_IDLE_TIME);
 
     NodeMainInstance main_instance(&params,
                                    uv_default_loop(),

diff --git a/src/node_perf.cc b/src/node_perf.cc
@@ -397,6 +397,13 @@ void Notify(const FunctionCallbackInfo<Value>& args) {
   }
 }
 
+// Return idle time of the event loop
+void LoopIdleTime(const FunctionCallbackInfo<Value>& args) {
+  Environment* env = Environment::GetCurrent(args);
+  uint64_t idle_time = uv_metrics_idle_time(env->event_loop());
+  args.GetReturnValue().Set(1.0 * idle_time / 1e6);
+}
+
 
 // Event Loop Timing Histogram
 namespace {
@@ -586,6 +593,7 @@ void Initialize(Local<Object> target,
                  "removeGarbageCollectionTracking",
                  RemoveGarbageCollectionTracking);
   env->SetMethod(target, "notify", Notify);
+  env->SetMethod(target, "loopIdleTime", LoopIdleTime);
 
   Local<Object> constants = Object::New(isolate);
 

diff --git a/src/node_worker.cc b/src/node_worker.cc
@@ -148,6 +148,7 @@ class WorkerThreadData {
       return;
     }
     loop_init_failed_ = false;
+    uv_loop_configure(&loop_, UV_METRICS_IDLE_TIME);
 
     Isolate::CreateParams params;
     SetIsolateCreateParamsForNode(&params);

diff --git a/test/parallel/test-performance-eventlooputil.js b/test/parallel/test-performance-eventlooputil.js
@@ -0,0 +1,99 @@
+'use strict';
+
+require('../common');
+
+const TIMEOUT = 50;
+
+const assert = require('assert');
+const { performance } = require('perf_hooks');
+const { Worker, parentPort } = require('worker_threads');
+
+const { nodeTiming, eventLoopUtilization } = performance;
+const elu = eventLoopUtilization();
+
+// Take into account whether this test was started as a Worker.
+if (nodeTiming.loopStart === -1) {
+  assert.strictEqual(nodeTiming.idleTime, 0);
+  assert.deepStrictEqual(elu, { idle: 0, active: 0, utilization: 0 });
+  assert.deepStrictEqual(eventLoopUtilization(elu),
+                         { idle: 0, active: 0, utilization: 0 });
+  assert.deepStrictEqual(eventLoopUtilization(elu, eventLoopUtilization()),
+                         { idle: 0, active: 0, utilization: 0 });
+}
+
+// Place in setTimeout() to make sure there is some idle time, but not going to
+// assert this since it could make the test flaky.
+setTimeout(() => {
+  const t = Date.now();
+  const elu1 = eventLoopUtilization();
+
+  while (Date.now() - t < 50) { }
+
+  const elu2 = eventLoopUtilization();
+  const elu3 = eventLoopUtilization(elu1);
+  const elu4 = eventLoopUtilization(elu2, elu1);
+
+  assert.strictEqual(elu3.idle, 0);
+  assert.strictEqual(elu4.idle, 0);
+  assert.strictEqual(elu3.utilization, 1);
+  assert.strictEqual(elu4.utilization, 1);
+  assert.strictEqual(elu2.active - elu1.active, elu4.active);
+  assert.ok(elu2.active > elu3.active);
+  assert.ok(elu2.active > elu4.active);
+  assert.ok(elu3.active > elu4.active);
+
+  setTimeout(runIdleTimeTest, TIMEOUT);
+}, 5);
+
+function runIdleTimeTest() {
+  const idleTime = nodeTiming.idleTime;
+  const elu1 = eventLoopUtilization();
+  const sum = elu1.idle + elu1.active;
+
+  assert.ok(sum >= elu1.idle && sum >= elu1.active,
+            `idle: ${elu1.idle}  active: ${elu1.active}  sum: ${sum}`);
+  assert.strictEqual(elu1.idle, idleTime);
+  assert.strictEqual(elu1.utilization, elu1.active / sum);
+
+  setTimeout(runCalcTest, TIMEOUT, elu1);
+}
+
+function runCalcTest(elu1) {
+  const now = performance.now();
+  const elu2 = eventLoopUtilization();
+  const elu3 = eventLoopUtilization(elu2, elu1);
+  const active_delta = elu2.active - elu1.active;
+  const idle_delta = elu2.idle - elu1.idle;
+
+  assert.ok(elu2.idle >= 0);
+  assert.ok(elu2.active >= 0);
+  assert.ok(elu3.idle >= 0);
+  assert.ok(elu3.active >= 0);
+  assert.ok(elu2.idle + elu2.active > elu1.idle + elu2.active);
+  assert.ok(elu2.idle + elu2.active >= now - nodeTiming.loopStart);
+  assert.strictEqual(elu3.active, elu2.active - elu1.active);
+  assert.strictEqual(elu3.idle, elu2.idle - elu1.idle);
+  assert.strictEqual(elu3.utilization,
+                     active_delta / (idle_delta + active_delta));
+
+  setImmediate(runWorkerTest);
+}
+
+function runWorkerTest() {
+  // Use argv to detect whether we're running as a Worker called by this test
+  // vs. this test also being called as a Worker.
+  if (process.argv[2] === 'iamalive') {
+    parentPort.postMessage(JSON.stringify(eventLoopUtilization()));
+    return;
+  }
+
+  const elu1 = eventLoopUtilization();
+  const worker = new Worker(__filename, { argv: [ 'iamalive' ] });
+
+  worker.on('message', (msg) => {
+    const elu2 = eventLoopUtilization(elu1);
+    const data = JSON.parse(msg);
+
+    assert.ok(elu2.active + elu2.idle > data.active + data.idle);
+  });
+}