From 47b1caffaf2467ddc29deb07b25ee9cf983bb99d Mon Sep 17 00:00:00 2001 From: Trevor Norris Date: Tue, 25 Aug 2020 13:36:37 -0600 Subject: [PATCH] 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. --- benchmark/README.md | 1 + benchmark/perf_hooks/bench-eventlooputil.js | 64 ++++++++++++ doc/api/perf_hooks.md | 71 +++++++++++++ lib/perf_hooks.js | 36 ++++++- src/node.cc | 1 + src/node_perf.cc | 8 ++ src/node_worker.cc | 1 + .../test-performance-eventlooputil.js | 99 +++++++++++++++++++ 8 files changed, 279 insertions(+), 2 deletions(-) create mode 100644 benchmark/perf_hooks/bench-eventlooputil.js create mode 100644 test/parallel/test-performance-eventlooputil.js 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 392dc2a5245104..c8770c25605370 100644 --- a/doc/api/perf_hooks.md +++ b/doc/api/perf_hooks.md @@ -165,6 +165,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)` @@ -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 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 d68c6d8d148a38..dd2cd0db75dc8a 100644 --- a/src/node.cc +++ b/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(¶ms, uv_default_loop(), diff --git a/src/node_perf.cc b/src/node_perf.cc index d71afc2d81c258..5fa4eabc9934de 100644 --- a/src/node_perf.cc +++ b/src/node_perf.cc @@ -440,6 +440,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 { @@ -629,6 +636,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 2b7cc156db9fbe..b3dd29bf9fb17b 100644 --- a/src/node_worker.cc +++ b/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 allocator = ArrayBufferAllocator::Create(); 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); + }); +}