Skip to content

Navigation Menu

Sign in
Appearance settings

Search code, repositories, users, issues, pull requests...

Provide feedback

We read every piece of feedback, and take your input very seriously.

Saved searches

Use saved searches to filter your results more quickly
Appearance settings

Commit 2c409a2

Browse filesBrowse files
trevnorrisaddaleax
trevnorris
authored and
addaleax
committed
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>
1 parent b117467 commit 2c409a2
Copy full SHA for 2c409a2

File tree

Expand file treeCollapse file tree

8 files changed

+279
-2
lines changed
Open diff view settings
Filter options
Expand file treeCollapse file tree

8 files changed

+279
-2
lines changed
Open diff view settings
Collapse file

‎benchmark/README.md‎

Copy file name to clipboardExpand all lines: benchmark/README.md
+1Lines changed: 1 addition & 0 deletions
  • Display the source diff
  • Display the rich diff
Original file line numberDiff line numberDiff line change
@@ -32,6 +32,7 @@ directory, see [the guide on benchmarks](../doc/guides/writing-and-running-bench
3232
| module | Benchmarks for the `module` subsystem. |
3333
| net | Benchmarks for the `net` subsystem. |
3434
| path | Benchmarks for the `path` subsystem. |
35+
| perf_hooks | Benchmarks for the `perf_hooks` subsystem. |
3536
| process | Benchmarks for the `process` subsystem. |
3637
| querystring | Benchmarks for the `querystring` subsystem. |
3738
| streams | Benchmarks for the `streams` subsystem. |
Collapse file

‎benchmark/perf_hooks/bench-eventlooputil.js‎

Copy file name to clipboard
+64Lines changed: 64 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,64 @@
1+
'use strict';
2+
3+
const common = require('../common.js');
4+
const assert = require('assert').ok;
5+
const { performance } = require('perf_hooks');
6+
const { nodeTiming, eventLoopUtilization } = performance;
7+
8+
const bench = common.createBenchmark(main, {
9+
n: [1e6],
10+
method: [
11+
'idleTime',
12+
'ELU_simple',
13+
'ELU_passed',
14+
],
15+
});
16+
17+
function main({ method, n }) {
18+
switch (method) {
19+
case 'idleTime':
20+
benchIdleTime(n);
21+
break;
22+
case 'ELU_simple':
23+
benchELUSimple(n);
24+
break;
25+
case 'ELU_passed':
26+
benchELUPassed(n);
27+
break;
28+
default:
29+
throw new Error(`Unsupported method ${method}`);
30+
}
31+
}
32+
33+
function benchIdleTime(n) {
34+
bench.start();
35+
for (let i = 0; i < n; i++)
36+
nodeTiming.idleTime;
37+
bench.end(n);
38+
}
39+
40+
function benchELUSimple(n) {
41+
// Need to put this in setImmediate or will always return 0.
42+
setImmediate(() => {
43+
const elu = eventLoopUtilization();
44+
assert(elu.active + elu.idle > 0);
45+
46+
bench.start();
47+
for (let i = 0; i < n; i++)
48+
eventLoopUtilization();
49+
bench.end(n);
50+
});
51+
}
52+
53+
function benchELUPassed(n) {
54+
// Need to put this in setImmediate or will always return 0.
55+
setImmediate(() => {
56+
let elu = eventLoopUtilization();
57+
assert(elu.active + elu.idle > 0);
58+
59+
bench.start();
60+
for (let i = 0; i < n; i++)
61+
elu = eventLoopUtilization(elu);
62+
bench.end(n);
63+
});
64+
}
Collapse file

‎doc/api/perf_hooks.md‎

Copy file name to clipboardExpand all lines: doc/api/perf_hooks.md
+71Lines changed: 71 additions & 0 deletions
  • Display the source diff
  • Display the rich diff
Original file line numberDiff line numberDiff line change
@@ -163,6 +163,62 @@ obs.observe({ entryTypes: ['function'] });
163163
wrapped();
164164
```
165165

166+
### `performance.eventLoopUtilization([util1][,util2])`
167+
<!-- YAML
168+
added: REPLACEME
169+
-->
170+
171+
* `util1` {Object} The result of a previous call to `eventLoopUtilization()`
172+
* `util2` {Object} The result of a previous call to `eventLoopUtilization()`
173+
prior to `util1`
174+
* Returns {Object}
175+
* `idle` {number}
176+
* `active` {number}
177+
* `utilization` {number}
178+
179+
The `eventLoopUtilization()` method returns an object that contains the
180+
cumulative duration of time the event loop has been both idle and active as a
181+
high resolution milliseconds timer. The `utilization` value is the calculated
182+
Event Loop Utilization (ELU). If bootstrapping has not yet finished, the
183+
properties have the value of 0.
184+
185+
`util1` and `util2` are optional parameters.
186+
187+
If `util1` is passed then the delta between the current call's `active` and
188+
`idle` times are calculated and returned (similar to [`process.hrtime()`][]).
189+
Likewise the adjusted `utilization` value is calculated.
190+
191+
If `util1` and `util2` are both passed then the calculation adjustments are
192+
done between the two arguments. This is a convenience option because unlike
193+
[`process.hrtime()`][] additional work is done to calculate the ELU.
194+
195+
ELU is similar to CPU utilization except that it is calculated using high
196+
precision wall-clock time. It represents the percentage of time the event loop
197+
has spent outside the event loop's event provider (e.g. `epoll_wait`). No other
198+
CPU idle time is taken into consideration. The following is an example of how
199+
a mostly idle process will have a high ELU.
200+
201+
<!-- eslint-skip -->
202+
```js
203+
'use strict';
204+
const { eventLoopUtilization } = require('perf_hooks').performance;
205+
const { spawnSync } = require('child_process');
206+
207+
setImmediate(() => {
208+
const elu = eventLoopUtilization();
209+
spawnSync('sleep', ['5']);
210+
console.log(eventLoopUtilization(elu).utilization);
211+
});
212+
```
213+
214+
While the CPU is mostly idle while running this script the value of
215+
`utilization` is 1. This is because the call to [`child_process.spawnSync()`][]
216+
blocks the event loop from proceeding.
217+
218+
Passing in a user-defined object instead of the result of a previous call to
219+
`eventLoopUtilization()` will lead to undefined behavior. The return values
220+
are not guaranteed to reflect any correct state of the event loop.
221+
166222
## Class: `PerformanceEntry`
167223
<!-- YAML
168224
added: v8.5.0
@@ -326,6 +382,19 @@ added: v8.5.0
326382
The high resolution millisecond timestamp at which the V8 platform was
327383
initialized.
328384

385+
### `performanceNodeTiming.idleTime`
386+
<!-- YAML
387+
added: REPLACEME
388+
-->
389+
390+
* {number}
391+
392+
The high resolution millisecond timestamp of the amount of time the event loop
393+
has been idle within the event loop's event provider (e.g. `epoll_wait`). This
394+
does not take CPU usage into consideration. If the event loop has not yet
395+
started (e.g., in the first tick of the main script), the property has the
396+
value of 0.
397+
329398
## Class: `perf_hooks.PerformanceObserver`
330399

331400
### `new PerformanceObserver(callback)`
@@ -682,6 +751,8 @@ require('some-module');
682751
```
683752

684753
[`'exit'`]: process.html#process_event_exit
754+
[`process.hrtime()`]: process.html#process_process_hrtime_time
755+
[`child_process.spawnSync()`]: #child_process_child_process_spawnsync_command_args_options
685756
[`timeOrigin`]: https://w3c.github.io/hr-time/#dom-performance-timeorigin
686757
[`window.performance`]: https://developer.mozilla.org/en-US/docs/Web/API/Window/performance
687758
[Async Hooks]: async_hooks.html
Collapse file

‎lib/perf_hooks.js‎

Copy file name to clipboardExpand all lines: lib/perf_hooks.js
+34-2Lines changed: 34 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -25,7 +25,8 @@ const {
2525
timerify,
2626
constants,
2727
installGarbageCollectionTracking,
28-
removeGarbageCollectionTracking
28+
removeGarbageCollectionTracking,
29+
loopIdleTime,
2930
} = internalBinding('performance');
3031

3132
const {
@@ -205,6 +206,10 @@ class PerformanceNodeTiming extends PerformanceEntry {
205206
return getMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_BOOTSTRAP_COMPLETE);
206207
}
207208

209+
get idleTime() {
210+
return loopIdleTime();
211+
}
212+
208213
[kInspect]() {
209214
return {
210215
name: 'node',
@@ -448,10 +453,37 @@ class Performance {
448453
return ret;
449454
}
450455

456+
eventLoopUtilization(util1, util2) {
457+
const ls = nodeTiming.loopStart;
458+
459+
if (ls <= 0) {
460+
return { idle: 0, active: 0, utilization: 0 };
461+
}
462+
463+
if (util2) {
464+
const idle = util1.idle - util2.idle;
465+
const active = util1.active - util2.active;
466+
return { idle, active, utilization: active / (idle + active) };
467+
}
468+
469+
const idle = nodeTiming.idleTime;
470+
const active = performance.now() - ls - idle;
471+
472+
if (!util1) {
473+
return { idle, active, utilization: active / (idle + active) };
474+
}
475+
476+
const idle_delta = idle - util1.idle;
477+
const active_delta = active - util1.active;
478+
const utilization = active_delta / (idle_delta + active_delta);
479+
return { idle: idle_delta, active: active_delta, utilization };
480+
}
481+
451482
[kInspect]() {
452483
return {
453484
nodeTiming: this.nodeTiming,
454-
timeOrigin: this.timeOrigin
485+
timeOrigin: this.timeOrigin,
486+
idleTime: this.idleTime,
455487
};
456488
}
457489
}
Collapse file

‎src/node.cc‎

Copy file name to clipboardExpand all lines: src/node.cc
+1Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -985,6 +985,7 @@ int Start(int argc, char** argv) {
985985
indexes = NodeMainInstance::GetIsolateDataIndexes();
986986
}
987987
}
988+
uv_loop_configure(uv_default_loop(), UV_METRICS_IDLE_TIME);
988989

989990
NodeMainInstance main_instance(&params,
990991
uv_default_loop(),
Collapse file

‎src/node_perf.cc‎

Copy file name to clipboardExpand all lines: src/node_perf.cc
+8Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -397,6 +397,13 @@ void Notify(const FunctionCallbackInfo<Value>& args) {
397397
}
398398
}
399399

400+
// Return idle time of the event loop
401+
void LoopIdleTime(const FunctionCallbackInfo<Value>& args) {
402+
Environment* env = Environment::GetCurrent(args);
403+
uint64_t idle_time = uv_metrics_idle_time(env->event_loop());
404+
args.GetReturnValue().Set(1.0 * idle_time / 1e6);
405+
}
406+
400407

401408
// Event Loop Timing Histogram
402409
namespace {
@@ -586,6 +593,7 @@ void Initialize(Local<Object> target,
586593
"removeGarbageCollectionTracking",
587594
RemoveGarbageCollectionTracking);
588595
env->SetMethod(target, "notify", Notify);
596+
env->SetMethod(target, "loopIdleTime", LoopIdleTime);
589597

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

Collapse file

‎src/node_worker.cc‎

Copy file name to clipboardExpand all lines: src/node_worker.cc
+1Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -148,6 +148,7 @@ class WorkerThreadData {
148148
return;
149149
}
150150
loop_init_failed_ = false;
151+
uv_loop_configure(&loop_, UV_METRICS_IDLE_TIME);
151152

152153
Isolate::CreateParams params;
153154
SetIsolateCreateParamsForNode(&params);
Collapse file

‎test/parallel/test-performance-eventlooputil.js‎

Copy file name to clipboard
+99Lines changed: 99 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,99 @@
1+
'use strict';
2+
3+
require('../common');
4+
5+
const TIMEOUT = 50;
6+
7+
const assert = require('assert');
8+
const { performance } = require('perf_hooks');
9+
const { Worker, parentPort } = require('worker_threads');
10+
11+
const { nodeTiming, eventLoopUtilization } = performance;
12+
const elu = eventLoopUtilization();
13+
14+
// Take into account whether this test was started as a Worker.
15+
if (nodeTiming.loopStart === -1) {
16+
assert.strictEqual(nodeTiming.idleTime, 0);
17+
assert.deepStrictEqual(elu, { idle: 0, active: 0, utilization: 0 });
18+
assert.deepStrictEqual(eventLoopUtilization(elu),
19+
{ idle: 0, active: 0, utilization: 0 });
20+
assert.deepStrictEqual(eventLoopUtilization(elu, eventLoopUtilization()),
21+
{ idle: 0, active: 0, utilization: 0 });
22+
}
23+
24+
// Place in setTimeout() to make sure there is some idle time, but not going to
25+
// assert this since it could make the test flaky.
26+
setTimeout(() => {
27+
const t = Date.now();
28+
const elu1 = eventLoopUtilization();
29+
30+
while (Date.now() - t < 50) { }
31+
32+
const elu2 = eventLoopUtilization();
33+
const elu3 = eventLoopUtilization(elu1);
34+
const elu4 = eventLoopUtilization(elu2, elu1);
35+
36+
assert.strictEqual(elu3.idle, 0);
37+
assert.strictEqual(elu4.idle, 0);
38+
assert.strictEqual(elu3.utilization, 1);
39+
assert.strictEqual(elu4.utilization, 1);
40+
assert.strictEqual(elu2.active - elu1.active, elu4.active);
41+
assert.ok(elu2.active > elu3.active);
42+
assert.ok(elu2.active > elu4.active);
43+
assert.ok(elu3.active > elu4.active);
44+
45+
setTimeout(runIdleTimeTest, TIMEOUT);
46+
}, 5);
47+
48+
function runIdleTimeTest() {
49+
const idleTime = nodeTiming.idleTime;
50+
const elu1 = eventLoopUtilization();
51+
const sum = elu1.idle + elu1.active;
52+
53+
assert.ok(sum >= elu1.idle && sum >= elu1.active,
54+
`idle: ${elu1.idle} active: ${elu1.active} sum: ${sum}`);
55+
assert.strictEqual(elu1.idle, idleTime);
56+
assert.strictEqual(elu1.utilization, elu1.active / sum);
57+
58+
setTimeout(runCalcTest, TIMEOUT, elu1);
59+
}
60+
61+
function runCalcTest(elu1) {
62+
const now = performance.now();
63+
const elu2 = eventLoopUtilization();
64+
const elu3 = eventLoopUtilization(elu2, elu1);
65+
const active_delta = elu2.active - elu1.active;
66+
const idle_delta = elu2.idle - elu1.idle;
67+
68+
assert.ok(elu2.idle >= 0);
69+
assert.ok(elu2.active >= 0);
70+
assert.ok(elu3.idle >= 0);
71+
assert.ok(elu3.active >= 0);
72+
assert.ok(elu2.idle + elu2.active > elu1.idle + elu2.active);
73+
assert.ok(elu2.idle + elu2.active >= now - nodeTiming.loopStart);
74+
assert.strictEqual(elu3.active, elu2.active - elu1.active);
75+
assert.strictEqual(elu3.idle, elu2.idle - elu1.idle);
76+
assert.strictEqual(elu3.utilization,
77+
active_delta / (idle_delta + active_delta));
78+
79+
setImmediate(runWorkerTest);
80+
}
81+
82+
function runWorkerTest() {
83+
// Use argv to detect whether we're running as a Worker called by this test
84+
// vs. this test also being called as a Worker.
85+
if (process.argv[2] === 'iamalive') {
86+
parentPort.postMessage(JSON.stringify(eventLoopUtilization()));
87+
return;
88+
}
89+
90+
const elu1 = eventLoopUtilization();
91+
const worker = new Worker(__filename, { argv: [ 'iamalive' ] });
92+
93+
worker.on('message', (msg) => {
94+
const elu2 = eventLoopUtilization(elu1);
95+
const data = JSON.parse(msg);
96+
97+
assert.ok(elu2.active + elu2.idle > data.active + data.idle);
98+
});
99+
}

0 commit comments

Comments
0 (0)
Morty Proxy This is a proxified and sanitized view of the page, visit original site.