From b8053afa707c200c950276aeeb30ed7d3bfd5170 Mon Sep 17 00:00:00 2001 From: Trevor Norris Date: Thu, 15 Oct 2020 14:42:02 -0600 Subject: [PATCH 1/2] test, doc: improve ELU test and fix doc error * Place all callbacks in mustCall(). * Force idle time to accumulate before allowing the test to proceed. * Add doc info that ELU is always available in worker threads. --- doc/api/perf_hooks.md | 8 ++- .../test-performance-eventlooputil.js | 51 +++++++++++-------- 2 files changed, 35 insertions(+), 24 deletions(-) diff --git a/doc/api/perf_hooks.md b/doc/api/perf_hooks.md index 267d71344bb0b7..bb22c09fddd7de 100644 --- a/doc/api/perf_hooks.md +++ b/doc/api/perf_hooks.md @@ -72,8 +72,11 @@ added: 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`. +Event Loop Utilization (ELU). + +If bootstrapping has not yet finished on the main thread the properties have +the value of `0`. The ELU is immediately available on [Worker threads][] since +bootstrap happens within the event loop. Both `utilization1` and `utilization2` are optional parameters. @@ -766,6 +769,7 @@ require('some-module'); [Performance Timeline]: https://w3c.github.io/performance-timeline/ [User Timing]: https://www.w3.org/TR/user-timing/ [Web Performance APIs]: https://w3c.github.io/perf-timing-primer/ +[Worker threads]: worker_threads.md#worker_threads_worker_threads [`'exit'`]: process.md#process_event_exit [`child_process.spawnSync()`]: child_process.md#child_process_child_process_spawnsync_command_args_options [`process.hrtime()`]: process.md#process_process_hrtime_time diff --git a/test/parallel/test-performance-eventlooputil.js b/test/parallel/test-performance-eventlooputil.js index 1a5d86db750a94..5d039209dadde7 100644 --- a/test/parallel/test-performance-eventlooputil.js +++ b/test/parallel/test-performance-eventlooputil.js @@ -1,8 +1,9 @@ 'use strict'; -require('../common'); +const { mustCall } = require('../common'); -const TIMEOUT = 50; +const TIMEOUT = 10; +const SPIN_DUR = 50; const assert = require('assert'); const { performance } = require('perf_hooks'); @@ -21,13 +22,15 @@ if (nodeTiming.loopStart === -1) { { 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(() => { +setTimeout(mustCall(function r() { const t = Date.now(); const elu1 = eventLoopUtilization(); - while (Date.now() - t < 50) { } + // Force idle time to accumulate before allowing test to continue. + if (elu1.idle <= 0) + return setTimeout(mustCall(r), 5); + + while (Date.now() - t < SPIN_DUR) { } const elu2 = eventLoopUtilization(); const elu3 = eventLoopUtilization(elu1); @@ -38,12 +41,13 @@ setTimeout(() => { 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); + assert.ok(elu3.active > SPIN_DUR - 10, `${elu3.active} <= ${SPIN_DUR - 10}`); + assert.ok(elu3.active > elu4.active, `${elu3.active} <= ${elu4.active}`); + assert.ok(elu2.active > elu3.active, `${elu2.active} <= ${elu3.active}`); + assert.ok(elu2.active > elu4.active, `${elu2.active} <= ${elu4.active}`); - setTimeout(runIdleTimeTest, TIMEOUT); -}, 5); + setTimeout(mustCall(runIdleTimeTest), TIMEOUT); +}), 5); function runIdleTimeTest() { const idleTime = nodeTiming.idleTime; @@ -55,7 +59,7 @@ function runIdleTimeTest() { assert.strictEqual(elu1.idle, idleTime); assert.strictEqual(elu1.utilization, elu1.active / sum); - setTimeout(runCalcTest, TIMEOUT, elu1); + setTimeout(mustCall(runCalcTest), TIMEOUT, elu1); } function runCalcTest(elu1) { @@ -65,18 +69,20 @@ function runCalcTest(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.ok(elu2.idle >= 0, `${elu2.idle} < 0`); + assert.ok(elu2.active >= 0, `${elu2.active} < 0`); + assert.ok(elu3.idle >= 0, `${elu3.idle} < 0`); + assert.ok(elu3.active >= 0, `${elu3.active} < 0`); + assert.ok(elu2.idle + elu2.active > elu1.idle + elu1.active, + `${elu2.idle + elu2.active} <= ${elu1.idle + elu1.active}`); + assert.ok(elu2.idle + elu2.active >= now - nodeTiming.loopStart, + `${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); + setImmediate(mustCall(runWorkerTest)); } function runWorkerTest() { @@ -90,10 +96,11 @@ function runWorkerTest() { const elu1 = eventLoopUtilization(); const worker = new Worker(__filename, { argv: [ 'iamalive' ] }); - worker.on('message', (msg) => { + worker.on('message', mustCall((msg) => { const elu2 = eventLoopUtilization(elu1); const data = JSON.parse(msg); - assert.ok(elu2.active + elu2.idle > data.active + data.idle); - }); + assert.ok(elu2.active + elu2.idle > data.active + data.idle, + `${elu2.active + elu2.idle} <= ${data.active + data.idle}`); + })); } From 076fa86f5008e9567bc508490a5af892f0edfed5 Mon Sep 17 00:00:00 2001 From: Trevor Norris Date: Wed, 14 Oct 2020 13:57:43 -0600 Subject: [PATCH 2/2] worker: add eventLoopUtilization() Allow calling eventLoopUtilization() directly on a worker thread: const worker = new Worker('./foo.js'); const elu = worker.performance.eventLoopUtilization(); setTimeout(() => { worker.performance.eventLoopUtilization(elu); }, 10); Add a new performance object on the Worker instance that will hopefully one day hold all the other performance metrics, such as nodeTiming. Include benchmarks and tests. --- benchmark/worker/bench-eventlooputil.js | 61 +++++++++++ doc/api/worker_threads.md | 62 +++++++++++ lib/internal/worker.js | 56 ++++++++++ src/node_worker.cc | 37 +++++++ src/node_worker.h | 2 + test/parallel/test-bootstrap-modules.js | 1 + test/parallel/test-worker-eventlooputil.js | 116 +++++++++++++++++++++ 7 files changed, 335 insertions(+) create mode 100644 benchmark/worker/bench-eventlooputil.js create mode 100644 test/parallel/test-worker-eventlooputil.js diff --git a/benchmark/worker/bench-eventlooputil.js b/benchmark/worker/bench-eventlooputil.js new file mode 100644 index 00000000000000..2d59f9f19ed563 --- /dev/null +++ b/benchmark/worker/bench-eventlooputil.js @@ -0,0 +1,61 @@ +'use strict'; + +const common = require('../common.js'); +const { Worker, parentPort } = require('worker_threads'); + +if (process.argv[2] === 'idle cats') { + return parentPort.once('message', () => {}); +} + +const bench = common.createBenchmark(main, { + n: [1e6], + method: [ + 'ELU_simple', + 'ELU_passed', + ], +}); + +function main({ method, n }) { + switch (method) { + case 'ELU_simple': + benchELUSimple(n); + break; + case 'ELU_passed': + benchELUPassed(n); + break; + default: + throw new Error(`Unsupported method ${method}`); + } +} + +function benchELUSimple(n) { + const worker = new Worker(__filename, { argv: ['idle cats'] }); + + spinUntilIdle(worker, () => { + bench.start(); + for (let i = 0; i < n; i++) + worker.performance.eventLoopUtilization(); + bench.end(n); + worker.postMessage('bye'); + }); +} + +function benchELUPassed(n) { + const worker = new Worker(__filename, { argv: ['idle cats'] }); + + spinUntilIdle(worker, () => { + let elu = worker.performance.eventLoopUtilization(); + bench.start(); + for (let i = 0; i < n; i++) + elu = worker.performance.eventLoopUtilization(elu); + bench.end(n); + worker.postMessage('bye'); + }); +} + +function spinUntilIdle(w, cb) { + const t = w.performance.eventLoopUtilization(); + if (t.idle + t.active > 0) + return process.nextTick(cb); + setTimeout(() => spinUntilIdle(w, cb), 1); +} diff --git a/doc/api/worker_threads.md b/doc/api/worker_threads.md index d361e5f5822839..4b04930db2fc6c 100644 --- a/doc/api/worker_threads.md +++ b/doc/api/worker_threads.md @@ -799,6 +799,65 @@ If the Worker thread is no longer running, which may occur before the [`'exit'` event][] is emitted, the returned `Promise` will be rejected immediately with an [`ERR_WORKER_NOT_RUNNING`][] error. +### `worker.performance` + + +An object that can be used to query performance information from a worker +instance. Similar to [`perf_hooks.performance`][]. + +#### `performance.eventLoopUtilization([utilization1[, utilization2]])` + + +* `utilization1` {Object} The result of a previous call to + `eventLoopUtilization()`. +* `utilization2` {Object} The result of a previous call to + `eventLoopUtilization()` prior to `utilization1`. +* Returns {Object} + * `idle` {number} + * `active` {number} + * `utilization` {number} + +The same call as [`perf_hooks` `eventLoopUtilization()`][], except the values +of the worker instance are returned. + +One difference is that, unlike the main thread, bootstrapping within a worker +is done within the event loop. So the event loop utilization will be +immediately available once the worker's script begins execution. + +An `idle` time that does not increase does not indicate that the worker is +stuck in bootstrap. The following examples shows how the worker's entire +lifetime will never accumulate any `idle` time, but is still be able to process +messages. + +```js +const { Worker, isMainThread, parentPort } = require('worker_threads'); + +if (isMainThread) { + const worker = new Worker(__filename); + setInterval(() => { + worker.postMessage('hi'); + console.log(worker.performance.eventLoopUtilization()); + }, 100).unref(); + return; +} + +parentPort.on('message', () => console.log('msg')).unref(); +(function r(n) { + if (--n < 0) return; + const t = Date.now(); + while (Date.now() - t < 300); + setImmediate(r, n); +})(10); +``` + +The event loop utilization of a worker is available only after the [`'online'` +event][] emitted, and if called before this, or after the [`'exit'` +event][], then all properties have the value of `0`. + ### `worker.postMessage(value[, transferList])`