diff --git a/doc/api/perf_hooks.md b/doc/api/perf_hooks.md index 61634056679062..7e9c86abf2935f 100644 --- a/doc/api/perf_hooks.md +++ b/doc/api/perf_hooks.md @@ -1704,23 +1704,32 @@ are not guaranteed to reflect any correct state of the event loop. * `options` {Object} - * `resolution` {number} The sampling rate in milliseconds. Must be greater - than zero. **Default:** `10`. -* Returns: {IntervalHistogram} + * `samplePerIteration` {boolean} When `true`, samples are taken once per + event loop iteration. **Default:** `false`. + * `resolution` {number} The sampling rate in milliseconds for interval-based + sampling. Must be greater than zero. This option is ignored when + `samplePerIteration` is `true`. **Default:** `10`. +* Returns: {ELDHistogram} _This property is an extension by Node.js. It is not available in Web browsers._ -Creates an `IntervalHistogram` object that samples and reports the event loop -delay over time. The delays will be reported in nanoseconds. +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. +By default, the histogram is updated by a timer using the configured +`resolution`. When `samplePerIteration` is `true`, samples are taken once per +event loop iteration using `uv_prepare_t` and `uv_check_t` hooks. In that mode, +the histogram does not keep the loop alive or force additional iterations when +the application is idle. +The two sampling modes produce significantly different results and should not +be compared directly. ```mjs import { monitorEventLoopDelay } from 'node:perf_hooks'; @@ -1997,9 +2006,10 @@ added: v11.10.0 The standard deviation of the recorded event loop delays. -## Class: `IntervalHistogram extends Histogram` +## Class: `ELDHistogram extends Histogram` -A `Histogram` that is periodically updated on a given interval. +A `Histogram` that records event loop delay, returned by +[`perf_hooks.monitorEventLoopDelay()`][]. ### `histogram.disable()` @@ -2009,7 +2019,7 @@ added: v11.10.0 * Returns: {boolean} -Disables the update interval timer. Returns `true` if the timer was +Disables event loop delay sampling. Returns `true` if sampling was stopped, `false` if it was already stopped. ### `histogram.enable()` @@ -2020,7 +2030,7 @@ added: v11.10.0 * Returns: {boolean} -Enables the update interval timer. Returns `true` if the timer was +Enables event loop delay sampling. Returns `true` if sampling was started, `false` if it was already started. ### `histogram[Symbol.dispose]()` @@ -2029,7 +2039,7 @@ started, `false` if it was already started. added: v24.2.0 --> -Disables the update interval timer when the histogram is disposed. +Disables event loop delay sampling when the histogram is disposed. ```js const { monitorEventLoopDelay } = require('node:perf_hooks'); @@ -2040,11 +2050,11 @@ const { monitorEventLoopDelay } = require('node:perf_hooks'); } ``` -### Cloning an `IntervalHistogram` +### Cloning an `ELDHistogram` -{IntervalHistogram} instances can be cloned via {MessagePort}. On the receiving -end, the histogram is cloned as a plain {Histogram} object that does not -implement the `enable()` and `disable()` methods. +{ELDHistogram} instances can be cloned via {MessagePort}. On the receiving end, +the histogram is cloned as a plain {Histogram} object that does not implement +the `enable()` and `disable()` methods. ## Class: `RecordableHistogram extends Histogram` @@ -2352,6 +2362,7 @@ dns.promises.resolve('localhost'); [`'exit'`]: process.md#event-exit [`child_process.spawnSync()`]: child_process.md#child_processspawnsynccommand-args-options [`perf_hooks.eventLoopUtilization()`]: #perf_hookseventlooputilizationutilization1-utilization2 +[`perf_hooks.monitorEventLoopDelay()`]: #perf_hooksmonitoreventloopdelayoptions [`perf_hooks.timerify()`]: #perf_hookstimerifyfn-options [`process.hrtime()`]: process.md#processhrtimetime [`timeOrigin`]: https://w3c.github.io/hr-time/#dom-performance-timeorigin diff --git a/lib/internal/perf/event_loop_delay.js b/lib/internal/perf/event_loop_delay.js index 17581b1310c5c0..ebf0017b70df85 100644 --- a/lib/internal/perf/event_loop_delay.js +++ b/lib/internal/perf/event_loop_delay.js @@ -18,6 +18,7 @@ const { } = internalBinding('performance'); const { + validateBoolean, validateInteger, validateObject, } = require('internal/validators'); @@ -74,6 +75,7 @@ class ELDHistogram extends Histogram { /** * @param {{ + * samplePerIteration : boolean, * resolution : number * }} [options] * @returns {ELDHistogram} @@ -81,14 +83,15 @@ class ELDHistogram extends Histogram { function monitorEventLoopDelay(options = kEmptyObject) { validateObject(options, 'options'); - const { resolution = 10 } = options; + const { samplePerIteration = false, resolution = 10 } = options; + validateBoolean(samplePerIteration, 'options.samplePerIteration'); validateInteger(resolution, 'options.resolution', 1); return ReflectConstruct( function() { markTransferMode(this, true, false); this[kEnabled] = false; - this[kHandle] = createELDHistogram(resolution); + this[kHandle] = createELDHistogram(resolution, samplePerIteration); this[kMap] = new SafeMap(); }, [], ELDHistogram); } diff --git a/src/env_properties.h b/src/env_properties.h index 6530f89ec918ac..99a9041f6f5ddd 100644 --- a/src/env_properties.h +++ b/src/env_properties.h @@ -431,6 +431,7 @@ V(http2ping_constructor_template, v8::ObjectTemplate) \ V(i18n_converter_template, v8::ObjectTemplate) \ V(intervalhistogram_constructor_template, v8::FunctionTemplate) \ + V(iterationhistogram_constructor_template, v8::FunctionTemplate) \ V(iter_template, v8::DictionaryTemplate) \ V(js_transferable_constructor_template, v8::FunctionTemplate) \ V(libuv_stream_wrap_ctor_template, v8::FunctionTemplate) \ diff --git a/src/histogram.cc b/src/histogram.cc index 8752a419ec4030..5dd82c305bf7ae 100644 --- a/src/histogram.cc +++ b/src/histogram.cc @@ -25,6 +25,20 @@ using v8::String; using v8::Uint32; using v8::Value; +template +void StartHandleHistogram(Local receiver, bool reset) { + T* histogram; + ASSIGN_OR_RETURN_UNWRAP(&histogram, receiver); + histogram->OnStart(reset ? T::StartFlags::RESET : T::StartFlags::NONE); +} + +template +void StopHandleHistogram(Local receiver) { + T* histogram; + ASSIGN_OR_RETURN_UNWRAP(&histogram, receiver); + histogram->OnStop(); +} + Histogram::Histogram(const Options& options) { hdr_histogram* histogram; CHECK_EQ(0, hdr_init(options.lowest, @@ -68,6 +82,10 @@ CFunction IntervalHistogram::fast_start_( CFunction::Make(&IntervalHistogram::FastStart)); CFunction IntervalHistogram::fast_stop_( CFunction::Make(&IntervalHistogram::FastStop)); +CFunction IterationHistogram::fast_start_( + CFunction::Make(&IterationHistogram::FastStart)); +CFunction IterationHistogram::fast_stop_( + CFunction::Make(&IterationHistogram::FastStop)); void HistogramImpl::AddMethods(Isolate* isolate, Local tmpl) { // TODO(@jasnell): The bigint API variations do not yet support fast @@ -419,29 +437,157 @@ void IntervalHistogram::OnStop() { } void IntervalHistogram::Start(const FunctionCallbackInfo& args) { - IntervalHistogram* histogram; - ASSIGN_OR_RETURN_UNWRAP(&histogram, args.This()); - histogram->OnStart(args[0]->IsTrue() ? StartFlags::RESET : StartFlags::NONE); + StartHandleHistogram(args.This(), args[0]->IsTrue()); } void IntervalHistogram::FastStart(Local receiver, bool reset) { TRACK_V8_FAST_API_CALL("histogram.start"); - IntervalHistogram* histogram; - ASSIGN_OR_RETURN_UNWRAP(&histogram, receiver); - histogram->OnStart(reset ? StartFlags::RESET : StartFlags::NONE); + StartHandleHistogram(receiver, reset); } void IntervalHistogram::Stop(const FunctionCallbackInfo& args) { - IntervalHistogram* histogram; - ASSIGN_OR_RETURN_UNWRAP(&histogram, args.This()); - histogram->OnStop(); + StopHandleHistogram(args.This()); } void IntervalHistogram::FastStop(Local receiver) { TRACK_V8_FAST_API_CALL("histogram.stop"); - IntervalHistogram* histogram; - ASSIGN_OR_RETURN_UNWRAP(&histogram, receiver); - histogram->OnStop(); + StopHandleHistogram(receiver); +} + +Local IterationHistogram::GetConstructorTemplate( + Environment* env) { + Local tmpl = env->iterationhistogram_constructor_template(); + if (tmpl.IsEmpty()) { + Isolate* isolate = env->isolate(); + tmpl = NewFunctionTemplate(isolate, nullptr); + tmpl->Inherit(HandleWrap::GetConstructorTemplate(env)); + tmpl->SetClassName(FIXED_ONE_BYTE_STRING(isolate, "Histogram")); + auto instance = tmpl->InstanceTemplate(); + instance->SetInternalFieldCount(IterationHistogram::kInternalFieldCount); + HistogramImpl::AddMethods(isolate, tmpl); + SetFastMethod(isolate, instance, "start", Start, &fast_start_); + SetFastMethod(isolate, instance, "stop", Stop, &fast_stop_); + env->set_iterationhistogram_constructor_template(tmpl); + } + return tmpl; +} + +void IterationHistogram::RegisterExternalReferences( + ExternalReferenceRegistry* registry) { + registry->Register(Start); + registry->Register(Stop); + registry->Register(fast_start_); + registry->Register(fast_stop_); + HistogramImpl::RegisterExternalReferences(registry); +} + +IterationHistogram::IterationHistogram(Environment* env, + Local wrap, + AsyncWrap::ProviderType type, + const Histogram::Options& options) + : HandleWrap( + env, wrap, reinterpret_cast(&check_handle_), type), + HistogramImpl(options) { + MakeWeak(); + wrap->SetAlignedPointerInInternalField( + HistogramImpl::InternalFields::kImplField, + static_cast(this), + EmbedderDataTag::kDefault); + uv_check_init(env->event_loop(), &check_handle_); + uv_prepare_init(env->event_loop(), &prepare_handle_); + uv_unref(reinterpret_cast(&check_handle_)); + uv_unref(reinterpret_cast(&prepare_handle_)); + prepare_handle_.data = this; +} + +BaseObjectPtr IterationHistogram::Create( + Environment* env, const Histogram::Options& options) { + Local obj; + if (!GetConstructorTemplate(env) + ->InstanceTemplate() + ->NewInstance(env->context()) + .ToLocal(&obj)) { + return nullptr; + } + + return MakeBaseObject( + env, obj, AsyncWrap::PROVIDER_ELDHISTOGRAM, options); +} + +void IterationHistogram::PrepareCB(uv_prepare_t* handle) { + IterationHistogram* self = static_cast(handle->data); + if (!self->enabled_) return; + self->prepare_time_ = uv_hrtime(); + self->timeout_ = uv_backend_timeout(handle->loop); +} + +void IterationHistogram::CheckCB(uv_check_t* handle) { + IterationHistogram* self = + ContainerOf(&IterationHistogram::check_handle_, handle); + if (!self->enabled_) return; + + uint64_t check_time = uv_hrtime(); + uint64_t poll_time = check_time - self->prepare_time_; + uint64_t latency = self->prepare_time_ - self->check_time_; + + if (self->timeout_ >= 0) { + uint64_t timeout_ns = static_cast(self->timeout_) * 1000 * 1000; + if (poll_time > timeout_ns) { + latency += poll_time - timeout_ns; + } + } + + self->histogram()->Record(latency == 0 ? 1 : latency); + self->check_time_ = check_time; +} + +void IterationHistogram::MemoryInfo(MemoryTracker* tracker) const { + tracker->TrackField("histogram", histogram()); +} + +void IterationHistogram::OnStart(StartFlags flags) { + if (enabled_ || IsHandleClosing()) return; + enabled_ = true; + if (flags == StartFlags::RESET) histogram()->Reset(); + check_time_ = uv_hrtime(); + prepare_time_ = check_time_; + timeout_ = 0; + uv_check_start(&check_handle_, CheckCB); + uv_prepare_start(&prepare_handle_, PrepareCB); + uv_unref(reinterpret_cast(&check_handle_)); + uv_unref(reinterpret_cast(&prepare_handle_)); +} + +void IterationHistogram::OnStop() { + if (!enabled_ || IsHandleClosing()) return; + enabled_ = false; + uv_check_stop(&check_handle_); + uv_prepare_stop(&prepare_handle_); +} + +void IterationHistogram::Close(Local close_callback) { + if (IsHandleClosing()) return; + OnStop(); + HandleWrap::Close(close_callback); + uv_close(reinterpret_cast(&prepare_handle_), nullptr); +} + +void IterationHistogram::Start(const FunctionCallbackInfo& args) { + StartHandleHistogram(args.This(), args[0]->IsTrue()); +} + +void IterationHistogram::FastStart(Local receiver, bool reset) { + TRACK_V8_FAST_API_CALL("histogram.eventLoopDelay.start"); + StartHandleHistogram(receiver, reset); +} + +void IterationHistogram::Stop(const FunctionCallbackInfo& args) { + StopHandleHistogram(args.This()); +} + +void IterationHistogram::FastStop(Local receiver) { + TRACK_V8_FAST_API_CALL("histogram.eventLoopDelay.stop"); + StopHandleHistogram(receiver); } void HistogramImpl::GetCount(const FunctionCallbackInfo& args) { @@ -607,6 +753,11 @@ HistogramImpl* HistogramImpl::FromJSObject(Local value) { HistogramImpl::kImplField, EmbedderDataTag::kDefault)); } +std::unique_ptr IterationHistogram::CloneForMessaging() + const { + return std::make_unique(histogram()); +} + std::unique_ptr IntervalHistogram::CloneForMessaging() const { return std::make_unique(histogram()); diff --git a/src/histogram.h b/src/histogram.h index 31c6564b9b1f12..b9f968e8347c2e 100644 --- a/src/histogram.h +++ b/src/histogram.h @@ -20,6 +20,11 @@ namespace node { class ExternalReferenceRegistry; +template +void StartHandleHistogram(v8::Local receiver, bool reset); +template +void StopHandleHistogram(v8::Local receiver); + constexpr int kDefaultHistogramFigures = 3; class Histogram : public MemoryRetainer { @@ -257,6 +262,11 @@ class IntervalHistogram final : public HandleWrap, public HistogramImpl { void OnStart(StartFlags flags = StartFlags::RESET); void OnStop(); + template + friend void StartHandleHistogram(v8::Local, bool); + template + friend void StopHandleHistogram(v8::Local); + bool enabled_ = false; int32_t interval_ = 0; std::function on_interval_; @@ -266,6 +276,68 @@ class IntervalHistogram final : public HandleWrap, public HistogramImpl { static v8::CFunction fast_stop_; }; +class IterationHistogram final : public HandleWrap, public HistogramImpl { + public: + enum InternalFields { + kInternalFieldCount = std::max( + HandleWrap::kInternalFieldCount, HistogramImpl::kInternalFieldCount), + }; + + enum class StartFlags { NONE, RESET }; + + static void RegisterExternalReferences(ExternalReferenceRegistry* registry); + + static v8::Local GetConstructorTemplate( + Environment* env); + + static BaseObjectPtr Create( + Environment* env, const Histogram::Options& options); + + IterationHistogram(Environment* env, + v8::Local wrap, + AsyncWrap::ProviderType type, + const Histogram::Options& options = Histogram::Options{}); + + static void Start(const v8::FunctionCallbackInfo& args); + static void Stop(const v8::FunctionCallbackInfo& args); + + static void FastStart(v8::Local receiver, bool reset); + static void FastStop(v8::Local receiver); + + BaseObject::TransferMode GetTransferMode() const override { + return TransferMode::kCloneable; + } + std::unique_ptr CloneForMessaging() const override; + + void Close( + v8::Local close_callback = v8::Local()) override; + + void MemoryInfo(MemoryTracker* tracker) const override; + SET_MEMORY_INFO_NAME(IterationHistogram) + SET_SELF_SIZE(IterationHistogram) + + private: + static void PrepareCB(uv_prepare_t* handle); + static void CheckCB(uv_check_t* handle); + void OnStart(StartFlags flags = StartFlags::RESET); + void OnStop(); + + template + friend void StartHandleHistogram(v8::Local, bool); + template + friend void StopHandleHistogram(v8::Local); + + bool enabled_ = false; + uv_prepare_t prepare_handle_; + uv_check_t check_handle_; + uint64_t prepare_time_ = 0; + uint64_t check_time_ = 0; + int64_t timeout_ = 0; + + static v8::CFunction fast_start_; + static v8::CFunction fast_stop_; +}; + } // namespace node #endif // defined(NODE_WANT_INTERNALS) && NODE_WANT_INTERNALS diff --git a/src/node_perf.cc b/src/node_perf.cc index e984fd4c3bf003..9900e08b974245 100644 --- a/src/node_perf.cc +++ b/src/node_perf.cc @@ -282,6 +282,12 @@ void CreateELDHistogram(const FunctionCallbackInfo& args) { Environment* env = Environment::GetCurrent(args); int64_t interval = args[0].As()->Value(); CHECK_GT(interval, 0); + if (args[1]->IsTrue()) { + BaseObjectPtr histogram = + IterationHistogram::Create(env, Histogram::Options{1}); + args.GetReturnValue().Set(histogram->object()); + return; + } BaseObjectPtr histogram = IntervalHistogram::Create(env, interval, [](Histogram& histogram) { uint64_t delta = histogram.RecordDelta(); @@ -413,6 +419,7 @@ void RegisterExternalReferences(ExternalReferenceRegistry* registry) { registry->Register(fast_performance_now); HistogramBase::RegisterExternalReferences(registry); IntervalHistogram::RegisterExternalReferences(registry); + IterationHistogram::RegisterExternalReferences(registry); } } // namespace performance } // namespace node diff --git a/src/node_task_queue.cc b/src/node_task_queue.cc index 0d40f3914b101e..396ed5c4758c16 100644 --- a/src/node_task_queue.cc +++ b/src/node_task_queue.cc @@ -76,9 +76,11 @@ void PromiseRejectCallback(PromiseRejectMessage message) { value = Undefined(isolate); rejectionsHandledAfter++; TRACE_COUNTER2(TRACING_CATEGORY_NODE2(promises, rejections), - "rejections", - "unhandled", unhandledRejections, - "handledAfter", rejectionsHandledAfter); + "rejections", + "unhandled", + unhandledRejections, + "handledAfter", + rejectionsHandledAfter); } else { return; } diff --git a/test/parallel/test-perf-hooks-monitor-event-loop-delay-fast-calls.js b/test/parallel/test-perf-hooks-monitor-event-loop-delay-fast-calls.js new file mode 100644 index 00000000000000..1954f52e441557 --- /dev/null +++ b/test/parallel/test-perf-hooks-monitor-event-loop-delay-fast-calls.js @@ -0,0 +1,26 @@ +// Flags: --allow-natives-syntax --expose-internals --no-warnings +'use strict'; + +const common = require('../common'); +const assert = require('assert'); + +const { internalBinding } = require('internal/test/binding'); +const { createELDHistogram } = internalBinding('performance'); + +const histogram = createELDHistogram(1, true); + +function testFastMethods() { + histogram.start(true); + histogram.stop(); +} + +eval('%PrepareFunctionForOptimization(testFastMethods)'); +testFastMethods(); +eval('%OptimizeFunctionOnNextCall(testFastMethods)'); +testFastMethods(); + +if (common.isDebug) { + const { getV8FastApiCallCount } = internalBinding('debug'); + assert.strictEqual(getV8FastApiCallCount('histogram.eventLoopDelay.start'), 1); + assert.strictEqual(getV8FastApiCallCount('histogram.eventLoopDelay.stop'), 1); +} diff --git a/test/sequential/test-performance-eventloopdelay.js b/test/sequential/test-performance-eventloopdelay.js index 66493318f5651d..ddd33372ec5e8e 100644 --- a/test/sequential/test-performance-eventloopdelay.js +++ b/test/sequential/test-performance-eventloopdelay.js @@ -49,6 +49,16 @@ const { sleep } = require('internal/util'); } ); }); + + [null, 'a', 1, {}, []].forEach((i) => { + assert.throws( + () => monitorEventLoopDelay({ samplePerIteration: i }), + { + name: 'TypeError', + code: 'ERR_INVALID_ARG_TYPE', + } + ); + }); } { @@ -114,6 +124,101 @@ const { sleep } = require('internal/util'); spinAWhile(); } +{ + const histogram = monitorEventLoopDelay({ samplePerIteration: true }); + histogram.enable(); + setTimeout(common.mustCall(() => { + histogram.disable(); + assert(histogram.count > 0, + `Expected samples to be recorded, got count=${histogram.count}`); + assert(histogram.min > 0); + assert(histogram.max > 0); + assert(histogram.mean > 0); + assert(histogram.percentiles.size > 0); + for (let n = 1; n < 100; n = n + 10) { + assert(histogram.percentile(n) >= 0); + } + // reset() should restore the histogram to its initial state + histogram.reset(); + assert.strictEqual(histogram.count, 0); + assert.strictEqual(histogram.max, 0); + assert.strictEqual(histogram.min, 9223372036854776000); + assert(Number.isNaN(histogram.mean)); + assert(Number.isNaN(histogram.stddev)); + assert.strictEqual(histogram.percentiles.size, 1); + }), common.platformTimeout(20)); +} + +{ + // enable()/disable() return values for ELDHistogram (samplePerIteration: true) + const histogram = monitorEventLoopDelay({ samplePerIteration: true }); + assert.strictEqual(histogram.enable(), true); + assert.strictEqual(histogram.enable(), false); // Already enabled, no-op + assert.strictEqual(histogram.disable(), true); + assert.strictEqual(histogram.disable(), false); // Already disabled, no-op + // Re-enabling after disable should work + assert.strictEqual(histogram.enable(), true); + setTimeout(common.mustCall(() => { + histogram.disable(); + assert(histogram.count > 0, + `Expected samples after re-enable, got count=${histogram.count}`); + }), common.platformTimeout(20)); +} + +{ + // Verify that samplePerIteration records exactly one sample per event loop iteration. + const N = 10; + const histogram = monitorEventLoopDelay({ samplePerIteration: true }); + histogram.enable(); + + let iterations = 0; + const verify = common.mustCall(() => { + histogram.disable(); + assert( + histogram.count >= N - 1, + `Expected at least ${N - 1} samples for ${N} iterations, got ${histogram.count}` + ); + }); + + function tick() { + if (++iterations < N) { + setImmediate(tick); + } else { + verify(); + } + } + setImmediate(tick); +} + +{ + // samplePerIteration should sample per event loop iteration, independent of + // the timer resolution used by the legacy monitorEventLoopDelay path. + const N = 10; + const histogram = monitorEventLoopDelay({ + samplePerIteration: true, + resolution: 60 * 1000, + }); + histogram.enable(); + + let iterations = 0; + const verify = common.mustCall(() => { + histogram.disable(); + assert( + histogram.count >= N - 1, + `Expected samples despite large resolution, got count=${histogram.count}` + ); + }); + + function tick() { + if (++iterations < N) { + setImmediate(tick); + } else { + verify(); + } + } + setImmediate(tick); +} + // Make sure that the histogram instances can be garbage-collected without // and not just implicitly destroyed when the Environment is torn down. process.on('exit', global.gc);