diff --git a/benchmark/README.md b/benchmark/README.md index 6a40d7af3e1fcf..dc02db4abd8d24 100644 --- 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 new file mode 100644 index 00000000000000..984b2b66aecbcf --- /dev/null +++ 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 index 5df28047ac3f64..0bcfd688531bcb 100644 --- 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])` + + +* `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. + + +```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` + +* {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 index 2ce0d29464a9bd..683dec3a90a61d 100644 --- 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 index 728785d5d2773d..e93ddecb872f56 100644 --- 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(¶ms, uv_default_loop(), diff --git a/src/node_perf.cc b/src/node_perf.cc index e5ce41c1b20731..b3d64cf5755539 100644 --- a/src/node_perf.cc +++ b/src/node_perf.cc @@ -397,6 +397,13 @@ void Notify(const FunctionCallbackInfo& args) { } } +// Return idle time of the event loop +void LoopIdleTime(const FunctionCallbackInfo& 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 target, "removeGarbageCollectionTracking", RemoveGarbageCollectionTracking); env->SetMethod(target, "notify", Notify); + env->SetMethod(target, "loopIdleTime", LoopIdleTime); Local constants = Object::New(isolate); diff --git a/src/node_worker.cc b/src/node_worker.cc index a85893a195519d..5988c55e7b92b8 100644 --- 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(¶ms); diff --git a/test/parallel/test-performance-eventlooputil.js b/test/parallel/test-performance-eventlooputil.js new file mode 100644 index 00000000000000..1a5d86db750a94 --- /dev/null +++ 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); + }); +}