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..1844a0ac5e6037 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,61 @@ 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); + CHECK_EQ(uv_check_init(env->event_loop(), &check_), 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 since + // both `prepare_` and `check_`. + if (is_precise() && !IsHandleClosing()) { + uv_close(reinterpret_cast(&prepare_), nullptr); + uv_close(reinterpret_cast(&check_), 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->RecordCoarseDelta(); + histogram->TraceHistogram(); } -bool ELDHistogram::RecordDelta() { +void ELDHistogram::CheckCallback(uv_check_t* handle) { + ELDHistogram* histogram = ContainerOf(&ELDHistogram::check_, handle); + histogram->RecordPreciseDelayStart(); +} + +void ELDHistogram::PrepareCallback(uv_prepare_t* handle) { + ELDHistogram* histogram = ContainerOf(&ELDHistogram::prepare_, handle); + histogram->RecordPreciseDelayStop(); + histogram->TraceHistogram(); +} + +void ELDHistogram::RecordCoarseDelta() { 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 +557,76 @@ bool ELDHistogram::RecordDelta() { } } prev_ = time; - return ret; +} + +void ELDHistogram::RecordPreciseDelayStart() { + prev_ = uv_hrtime(); +} + +void ELDHistogram::RecordPreciseDelayStop() { + if (prev_ == 0) { + return; + } + + uint64_t time = uv_hrtime(); + int64_t delta = time - prev_; + if (delta <= 0) { + return; + } + bool ret = Record(delta); + TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop), + "delay", delta); + if (ret) { + return; + } + if (exceeds_ < 0xFFFFFFFF) { + exceeds_++; + } + ProcessEmitWarning( + env(), + "Event loop delay exceeded 1 hour: %" PRId64 " nanoseconds", + delta); } 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()) { + // `uv_prepare_start`/`uv_check_start` prepend the handles to the queue. + // Newly started handles will have their callbacks invoked **before** the + // old handles' callbacks. + // + // This is important because of `immediate_check_handle` in `src/env.cc`. + // `immediate_check_handle` is used for invoking user callbacks queued with + // `setImmediate()` API call. `ELDHistogram` has to record the delay + // induced by `setImmediate()` callbacks too so the order of handles is + // important. + CHECK_EQ(uv_prepare_start(&prepare_, PrepareCallback), 0); + CHECK_EQ(uv_check_start(&check_, CheckCallback), 0); + uv_unref(reinterpret_cast(&prepare_)); + uv_unref(reinterpret_cast(&check_)); + } 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); + CHECK_EQ(uv_check_stop(&check_), 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..f89b2293c03810 100644 --- a/src/node_perf.h +++ b/src/node_perf.h @@ -153,7 +153,10 @@ class ELDHistogram : public HandleWrap, public Histogram { Local wrap, int32_t resolution); - bool RecordDelta(); + void RecordCoarseDelta(); + void RecordPreciseDelayStart(); + void RecordPreciseDelayStop(); + void TraceHistogram(); bool Enable(); bool Disable(); void ResetState() { @@ -163,6 +166,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 +177,20 @@ class ELDHistogram : public HandleWrap, public Histogram { private: static void DelayIntervalCallback(uv_timer_t* req); + static void PrepareCallback(uv_prepare_t* handle); + static void CheckCallback(uv_check_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_; + uv_check_t check_; }; } // namespace performance 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() {