Skip to content

Commit

Permalink
perf_hooks: add idleTime and event loop util
Browse files Browse the repository at this point in the history
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>
  • Loading branch information
trevnorris authored and richardlau committed Sep 1, 2020
1 parent 1589f0e commit 8aac42c
Show file tree
Hide file tree
Showing 8 changed files with 279 additions and 2 deletions.
1 change: 1 addition & 0 deletions benchmark/README.md
Original file line number Diff line number Diff line change
Expand Up @@ -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. |
Expand Down
64 changes: 64 additions & 0 deletions benchmark/perf_hooks/bench-eventlooputil.js
Original file line number Diff line number Diff line change
@@ -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);
});
}
71 changes: 71 additions & 0 deletions doc/api/perf_hooks.md
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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)`
Expand Down Expand Up @@ -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
Expand Down
36 changes: 34 additions & 2 deletions lib/perf_hooks.js
Original file line number Diff line number Diff line change
Expand Up @@ -25,7 +25,8 @@ const {
timerify,
constants,
installGarbageCollectionTracking,
removeGarbageCollectionTracking
removeGarbageCollectionTracking,
loopIdleTime,
} = internalBinding('performance');

const {
Expand Down Expand Up @@ -205,6 +206,10 @@ class PerformanceNodeTiming extends PerformanceEntry {
return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_BOOTSTRAP_COMPLETE);
}

get idleTime() {
return loopIdleTime();
}

[kInspect]() {
return {
name: 'node',
Expand Down Expand Up @@ -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,
};
}
}
Expand Down
1 change: 1 addition & 0 deletions src/node.cc
Original file line number Diff line number Diff line change
Expand Up @@ -1089,6 +1089,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(),
Expand Down
8 changes: 8 additions & 0 deletions src/node_perf.cc
Original file line number Diff line number Diff line change
Expand Up @@ -394,6 +394,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 {
Expand Down Expand Up @@ -583,6 +590,7 @@ void Initialize(Local<Object> target,
"removeGarbageCollectionTracking",
RemoveGarbageCollectionTracking);
env->SetMethod(target, "notify", Notify);
env->SetMethod(target, "loopIdleTime", LoopIdleTime);

Local<Object> constants = Object::New(isolate);

Expand Down
1 change: 1 addition & 0 deletions src/node_worker.cc
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Expand Down
99 changes: 99 additions & 0 deletions test/parallel/test-performance-eventlooputil.js
Original file line number Diff line number Diff line change
@@ -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);
});
}

0 comments on commit 8aac42c

Please sign in to comment.