perf_hooks: add idleTime and event loop util

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.                                                                          |

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);
+  });
+}

doc/api/perf_hooks.md

@@ -165,6 +165,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
@@ -332,6 +388,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)`
@@ -688,6 +757,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

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,
     };
   }
 }

src/node.cc

@@ -1079,6 +1079,7 @@ int Start(int argc, char** argv) {
         env_info = NodeMainInstance::GetEnvSerializeInfo();
       }
     }
+    uv_loop_configure(uv_default_loop(), UV_METRICS_IDLE_TIME);
 
     NodeMainInstance main_instance(&params,
                                    uv_default_loop(),

src/node_perf.cc

@@ -440,6 +440,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 {
@@ -629,6 +636,7 @@ void Initialize(Local<Object> target,
                  "removeGarbageCollectionTracking",
                  RemoveGarbageCollectionTracking);
   env->SetMethod(target, "notify", Notify);
+  env->SetMethod(target, "loopIdleTime", LoopIdleTime);
 
   Local<Object> constants = Object::New(isolate);
 

src/node_worker.cc

@@ -135,6 +135,7 @@ class WorkerThreadData {
       return;
     }
     loop_init_failed_ = false;
+    uv_loop_configure(&loop_, UV_METRICS_IDLE_TIME);
 
     std::shared_ptr<ArrayBufferAllocator> allocator =
         ArrayBufferAllocator::Create();

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);
+  });
+}