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>

Author: trevnorris

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. |

benchmark/perf_hooks/bench-eventlooputil.js

@@ -0,0 +1,64 @@
+'use strict';
+
+constcommon=require('../common.js');
+constassert=require('assert').ok;
+const{ performance }=require('perf_hooks');
+const{ nodeTiming, eventLoopUtilization }=performance;
+
+constbench=common.createBenchmark(main,{
+n: [1e6],
+method: [
+'idleTime',
+'ELU_simple',
+'ELU_passed',
+],
+});
+
+functionmain({ method, n }){
+switch(method){
+case'idleTime':
+benchIdleTime(n);
+break;
+case'ELU_simple':
+benchELUSimple(n);
+break;
+case'ELU_passed':
+benchELUPassed(n);
+break;
+default:
+thrownewError(`Unsupported method ${method}`);
+}
+}
+
+functionbenchIdleTime(n){
+bench.start();
+for(leti=0;i<n;i++)
+nodeTiming.idleTime;
+bench.end(n);
+}
+
+functionbenchELUSimple(n){
+// Need to put this in setImmediate or will always return 0.
+setImmediate(()=>{
+constelu=eventLoopUtilization();
+assert(elu.active+elu.idle>0);
+
+bench.start();
+for(leti=0;i<n;i++)
+eventLoopUtilization();
+bench.end(n);
+});
+}
+
+functionbenchELUPassed(n){
+// Need to put this in setImmediate or will always return 0.
+setImmediate(()=>{
+letelu=eventLoopUtilization();
+assert(elu.active+elu.idle>0);
+
+bench.start();
+for(leti=0;i<n;i++)
+elu=eventLoopUtilization(elu);
+bench.end(n);
+});
+}

doc/api/perf_hooks.md

@@ -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(() => {
+constelu=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
@@ -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)`
@@ -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

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 {
 returngetMilestoneTimestamp(NODE_PERFORMANCE_MILESTONE_BOOTSTRAP_COMPLETE);
 }
 
+getidleTime(){
+returnloopIdleTime();
+}
+
 [kInspect](){
 return{
 name: 'node',
@@ -448,10 +453,37 @@ class Performance {
 returnret;
 }
 
+eventLoopUtilization(util1,util2){
+constls=nodeTiming.loopStart;
+
+if(ls<=0){
+return{idle: 0,active: 0,utilization: 0};
+}
+
+if(util2){
+constidle=util1.idle-util2.idle;
+constactive=util1.active-util2.active;
+return{ idle, active,utilization: active/(idle+active)};
+}
+
+constidle=nodeTiming.idleTime;
+constactive=performance.now()-ls-idle;
+
+if(!util1){
+return{ idle, active,utilization: active/(idle+active)};
+}
+
+constidle_delta=idle-util1.idle;
+constactive_delta=active-util1.active;
+constutilization=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,
 };
 }
 }

src/node.cc

@@ -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(),

src/node_perf.cc

@@ -394,6 +394,13 @@ void Notify(const FunctionCallbackInfo<Value>& args) {
  }
 }
 
+// Return idle time of the event loop
+voidLoopIdleTime(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 {
@@ -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);
 

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<ArrayBufferAllocator> allocator =
 ArrayBufferAllocator::Create();

test/parallel/test-performance-eventlooputil.js

@@ -0,0 +1,99 @@
+'use strict';
+
+require('../common');
+
+constTIMEOUT=50;
+
+constassert=require('assert');
+const{ performance }=require('perf_hooks');
+const{ Worker, parentPort }=require('worker_threads');
+
+const{ nodeTiming, eventLoopUtilization }=performance;
+constelu=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(()=>{
+constt=Date.now();
+constelu1=eventLoopUtilization();
+
+while(Date.now()-t<50){}
+
+constelu2=eventLoopUtilization();
+constelu3=eventLoopUtilization(elu1);
+constelu4=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);
+
+functionrunIdleTimeTest(){
+constidleTime=nodeTiming.idleTime;
+constelu1=eventLoopUtilization();
+constsum=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);
+}
+
+functionrunCalcTest(elu1){
+constnow=performance.now();
+constelu2=eventLoopUtilization();
+constelu3=eventLoopUtilization(elu2,elu1);
+constactive_delta=elu2.active-elu1.active;
+constidle_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);
+}
+
+functionrunWorkerTest(){
+// 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;
+}
+
+constelu1=eventLoopUtilization();
+constworker=newWorker(__filename,{argv: ['iamalive']});
+
+worker.on('message',(msg)=>{
+constelu2=eventLoopUtilization(elu1);
+constdata=JSON.parse(msg);
+
+assert.ok(elu2.active+elu2.idle>data.active+data.idle);
+});
+}