From 4536077af00d0be44687a21619eccdef0b75ff7b Mon Sep 17 00:00:00 2001 From: Fedor Indutny Date: Fri, 28 Feb 2020 21:07:37 -0800 Subject: [PATCH 1/3] perf_hooks: precise mode for monitorEventLoopDelay Introduce precise mode of `monitorEventLoopDelay` by using `uv_prepare_t` to calculate time difference between two `uv_prepare_t` callbacks. --- doc/api/perf_hooks.md | 27 +++++-- lib/perf_hooks.js | 4 +- src/node_perf.cc | 74 ++++++++++++++----- src/node_perf.h | 11 ++- ...st-performance-eventloopdelay-reporting.js | 64 ++++++++++++++++ .../test-performance-eventloopdelay.js | 6 +- 6 files changed, 153 insertions(+), 33 deletions(-) create mode 100644 test/sequential/test-performance-eventloopdelay-reporting.js diff --git a/doc/api/perf_hooks.md b/doc/api/perf_hooks.md index 00b52d96889c61..04cf8f5ce1995b 100644 --- a/doc/api/perf_hooks.md +++ b/doc/api/perf_hooks.md @@ -432,21 +432,34 @@ is equal to `type`. ## `perf_hooks.monitorEventLoopDelay([options])` * `options` {Object} - * `resolution` {number} The sampling rate in milliseconds. Must be greater - than zero. **Default:** `10`. + * `resolution` {number} Optional sampling rate in milliseconds. Must be + greater or equal to zero. **Default:** `0`. * Returns: {Histogram} Creates a `Histogram` object that samples and reports the event loop delay over time. The delays will be reported in nanoseconds. -Using a timer to detect approximate event loop delay works because the -execution of timers is tied specifically to the lifecycle of the libuv -event loop. That is, a delay in the loop will cause a delay in the execution -of the timer, and those delays are specifically what this API is intended to -detect. +When `resolution` is zero a precise time difference between IO poll end and IO +poll start is entered into the histogram on every event-loop iteration. During +standby (i.e., no event-loop activity) - no data is added to the histogram, as +would be expected. + +When `resolution` is non-zero a timer is used to detect approximate event loop +delay. This works because the execution of timers is tied specifically to the +lifecycle of the libuv event loop. That is, a delay in the loop will cause a +delay in the execution of the timer, and those delays are specifically what this +API is intended to detect. Timer-based monitoring happens continuously and adds +delay statistics to the histogram even during standby when the Node.js would not +otherwise be consuming CPU. Since this approach just checks the loop state +periodically, it can easily miss loops that had excessive delays. ```js const { monitorEventLoopDelay } = require('perf_hooks'); diff --git a/lib/perf_hooks.js b/lib/perf_hooks.js index 267b4577ffee3d..0454c5a0278206 100644 --- a/lib/perf_hooks.js +++ b/lib/perf_hooks.js @@ -604,12 +604,12 @@ function monitorEventLoopDelay(options = {}) { if (typeof options !== 'object' || options === null) { throw new ERR_INVALID_ARG_TYPE('options', 'Object', options); } - const { resolution = 10 } = options; + const { resolution = 0 } = options; if (typeof resolution !== 'number') { throw new ERR_INVALID_ARG_TYPE('options.resolution', 'number', resolution); } - if (resolution <= 0 || !NumberIsSafeInteger(resolution)) { + if (resolution < 0 || !NumberIsSafeInteger(resolution)) { throw new ERR_INVALID_OPT_VALUE.RangeError('resolution', resolution); } return new ELDHistogram(new _ELDHistogram(resolution)); diff --git a/src/node_perf.cc b/src/node_perf.cc index 68b015f33eda49..96f7376ef93f23 100644 --- a/src/node_perf.cc +++ b/src/node_perf.cc @@ -474,7 +474,7 @@ static void ELDHistogramNew(const FunctionCallbackInfo& args) { Environment* env = Environment::GetCurrent(args); CHECK(args.IsConstructCall()); int32_t resolution = args[0]->IntegerValue(env->context()).FromJust(); - CHECK_GT(resolution, 0); + CHECK_GE(resolution, 0); new ELDHistogram(env, args.This(), resolution); } } // namespace @@ -489,29 +489,53 @@ ELDHistogram::ELDHistogram( Histogram(1, 3.6e12), resolution_(resolution) { MakeWeak(); - uv_timer_init(env->event_loop(), &timer_); + + // Since we pass `timer_` to `HandleWrap` constructor - we have to + // initialize it here. It is equally important to have it initialized for + // correct operation of `Close()` below. + CHECK_EQ(uv_timer_init(env->event_loop(), &timer_), 0); + + if (is_precise()) { + CHECK_EQ(uv_prepare_init(env->event_loop(), &prepare_), 0); + } +} + +void ELDHistogram::Close(Local close_callback) { + // HandleWrap::Close will call `uv_close()` on `timer_` and + // deallocate `ELDHistogram` in `HandleWrap::OnClose`. + // Therefore, it is safe to call `uv_close` with `nullptr` here. + if (is_precise() && !IsHandleClosing()) { + uv_close(reinterpret_cast(&prepare_), nullptr); + } + + HandleWrap::Close(close_callback); +} + +void ELDHistogram::TraceHistogram() { + TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop), "min", Min()); + TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop), "max", Max()); + TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop), "mean", Mean()); + TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop), "stddev", Stddev()); } void ELDHistogram::DelayIntervalCallback(uv_timer_t* req) { ELDHistogram* histogram = ContainerOf(&ELDHistogram::timer_, req); histogram->RecordDelta(); - TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop), - "min", histogram->Min()); - TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop), - "max", histogram->Max()); - TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop), - "mean", histogram->Mean()); - TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop), - "stddev", histogram->Stddev()); + histogram->TraceHistogram(); } -bool ELDHistogram::RecordDelta() { +void ELDHistogram::PrepareCallback(uv_prepare_t* handle) { + ELDHistogram* histogram = ContainerOf(&ELDHistogram::prepare_, handle); + histogram->RecordDelta(); + histogram->TraceHistogram(); +} + +void ELDHistogram::RecordDelta() { uint64_t time = uv_hrtime(); - bool ret = true; if (prev_ > 0) { int64_t delta = time - prev_; if (delta > 0) { - ret = Record(delta); + bool ret = Record(delta); TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop), "delay", delta); if (!ret) { @@ -525,25 +549,35 @@ bool ELDHistogram::RecordDelta() { } } prev_ = time; - return ret; } bool ELDHistogram::Enable() { if (enabled_ || IsHandleClosing()) return false; enabled_ = true; prev_ = 0; - uv_timer_start(&timer_, - DelayIntervalCallback, - resolution_, - resolution_); - uv_unref(reinterpret_cast(&timer_)); + + if (is_precise()) { + CHECK_EQ(uv_prepare_start(&prepare_, PrepareCallback), 0); + uv_unref(reinterpret_cast(&prepare_)); + } else { + CHECK_EQ(uv_timer_start(&timer_, + DelayIntervalCallback, + resolution_, + resolution_), + 0); + uv_unref(reinterpret_cast(&timer_)); + } return true; } bool ELDHistogram::Disable() { if (!enabled_ || IsHandleClosing()) return false; enabled_ = false; - uv_timer_stop(&timer_); + if (is_precise()) { + CHECK_EQ(uv_prepare_stop(&prepare_), 0); + } else { + CHECK_EQ(uv_timer_stop(&timer_), 0); + } return true; } diff --git a/src/node_perf.h b/src/node_perf.h index 4f5ca93f223289..104647c94be42c 100644 --- a/src/node_perf.h +++ b/src/node_perf.h @@ -153,7 +153,8 @@ class ELDHistogram : public HandleWrap, public Histogram { Local wrap, int32_t resolution); - bool RecordDelta(); + void RecordDelta(); + void TraceHistogram(); bool Enable(); bool Disable(); void ResetState() { @@ -163,6 +164,8 @@ class ELDHistogram : public HandleWrap, public Histogram { } int64_t Exceeds() { return exceeds_; } + void Close(Local close_callback = Local()) override; + void MemoryInfo(MemoryTracker* tracker) const override { tracker->TrackFieldWithSize("histogram", GetMemorySize()); } @@ -172,12 +175,18 @@ class ELDHistogram : public HandleWrap, public Histogram { private: static void DelayIntervalCallback(uv_timer_t* req); + static void PrepareCallback(uv_prepare_t* handle); + + inline bool is_precise() const { + return resolution_ == 0; + } bool enabled_ = false; int32_t resolution_ = 0; int64_t exceeds_ = 0; uint64_t prev_ = 0; uv_timer_t timer_; + uv_prepare_t prepare_; }; } // namespace performance diff --git a/test/sequential/test-performance-eventloopdelay-reporting.js b/test/sequential/test-performance-eventloopdelay-reporting.js new file mode 100644 index 00000000000000..9810ab4be6ee61 --- /dev/null +++ b/test/sequential/test-performance-eventloopdelay-reporting.js @@ -0,0 +1,64 @@ +// Flags: --expose-internals +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const net = require('net'); +const { + monitorEventLoopDelay +} = require('perf_hooks'); +const { sleep } = require('internal/util'); + +const ASYNC_SCHEDULERS = [ + (cb) => setTimeout(cb, common.platformTimeout(10)), + (cb) => { + const server = net.createServer((s) => { + s.destroy(); + server.close(); + + cb(); + }); + server.listen(0, () => { + const { port, address: host } = server.address(); + net.connect(port, host, () => { + }); + }); + }, +]; + +async function testSingle(resolution, callback) { + const histogram = monitorEventLoopDelay({ resolution }); + histogram.enable(); + + for (const schedule of ASYNC_SCHEDULERS) { + histogram.reset(); + + const msSleep = common.platformTimeout(100); + + await new Promise((resolve, reject) => { + schedule(() => { + sleep(msSleep); + resolve(); + }); + }); + + // Let the new event loop tick start + await new Promise((resolve, reject) => setTimeout(resolve, 10)); + + // Convert sleep time to nanoseconds + const nsSleep = msSleep * 1e6; + + // We are generous + assert(histogram.max >= 0.75 * nsSleep, + `${histogram.max} must be greater or equal to ${0.75 * nsSleep}`); + } + + histogram.disable(); +} + +async function test() { + await testSingle(0); + await testSingle(1); +} + +test(); diff --git a/test/sequential/test-performance-eventloopdelay.js b/test/sequential/test-performance-eventloopdelay.js index 47c54a2543fd54..408e4ea359ee3e 100644 --- a/test/sequential/test-performance-eventloopdelay.js +++ b/test/sequential/test-performance-eventloopdelay.js @@ -39,7 +39,7 @@ const { sleep } = require('internal/util'); ); }); - [-1, 0, Infinity].forEach((i) => { + [-1, Infinity].forEach((i) => { assert.throws( () => monitorEventLoopDelay({ resolution: i }), { @@ -50,8 +50,8 @@ const { sleep } = require('internal/util'); }); } -{ - const histogram = monitorEventLoopDelay({ resolution: 1 }); +for (const resolution of [ 0, 1 ]) { + const histogram = monitorEventLoopDelay({ resolution }); histogram.enable(); let m = 5; function spinAWhile() { From f8dc234803959eb70d61b941eaa45cf1f2cfd2e2 Mon Sep 17 00:00:00 2001 From: Fedor Indutny Date: Wed, 4 Mar 2020 20:34:13 -0800 Subject: [PATCH 2/3] test: lint --- test/sequential/test-performance-eventloopdelay-reporting.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/sequential/test-performance-eventloopdelay-reporting.js b/test/sequential/test-performance-eventloopdelay-reporting.js index 9810ab4be6ee61..0b3aee911aa194 100644 --- a/test/sequential/test-performance-eventloopdelay-reporting.js +++ b/test/sequential/test-performance-eventloopdelay-reporting.js @@ -50,7 +50,7 @@ async function testSingle(resolution, callback) { // We are generous assert(histogram.max >= 0.75 * nsSleep, - `${histogram.max} must be greater or equal to ${0.75 * nsSleep}`); + `${histogram.max} must be greater or equal to ${0.75 * nsSleep}`); } histogram.disable(); From 4ae2f1a04ddb8f3165e804463248acd5bda4e9d0 Mon Sep 17 00:00:00 2001 From: Fedor Indutny Date: Wed, 4 Mar 2020 20:49:58 -0800 Subject: [PATCH 3/3] test: fixes? --- .../test-performance-eventloopdelay-reporting.js | 9 ++++----- 1 file changed, 4 insertions(+), 5 deletions(-) diff --git a/test/sequential/test-performance-eventloopdelay-reporting.js b/test/sequential/test-performance-eventloopdelay-reporting.js index 0b3aee911aa194..b1a540e4005671 100644 --- a/test/sequential/test-performance-eventloopdelay-reporting.js +++ b/test/sequential/test-performance-eventloopdelay-reporting.js @@ -12,16 +12,15 @@ const { sleep } = require('internal/util'); const ASYNC_SCHEDULERS = [ (cb) => setTimeout(cb, common.platformTimeout(10)), (cb) => { - const server = net.createServer((s) => { + const server = net.createServer(common.mustCall((s) => { s.destroy(); server.close(); cb(); - }); + })); server.listen(0, () => { - const { port, address: host } = server.address(); - net.connect(port, host, () => { - }); + const { port } = server.address(); + net.connect(port, common.mustCall(() => {})); }); }, ];