Skip to content

Commit c5635b8

Browse files
authored
perf_hooks: sample delay per event loop iteration
Add a samplePerIteration option to monitorEventLoopDelay that records event loop delay from libuv event loop iterations instead of the timer interval sampler. The default remains interval-based; existing uses of monitorEventLoopDelay() keep behaving the same unless the samplePerIteration option is passed through. Signed-off-by: Pablo Erhard <pablo.erhardhernandez@datadoghq.com> PR-URL: #62935 Reviewed-By: Bryan English <bryan@bryanenglish.com> Reviewed-By: Ruben Bridgewater <ruben@bridgewater.de> Reviewed-By: James M Snell <jasnell@gmail.com>
1 parent cc37ad5 commit c5635b8

9 files changed

Lines changed: 414 additions & 36 deletions

File tree

doc/api/perf_hooks.md

Lines changed: 30 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -1706,23 +1706,32 @@ are not guaranteed to reflect any correct state of the event loop.
17061706

17071707
<!-- YAML
17081708
added: v11.10.0
1709+
changes:
1710+
- version: REPLACEME
1711+
pr-url: https://github.com/nodejs/node/pull/62935
1712+
description: Added the `samplePerIteration` option.
17091713
-->
17101714

17111715
* `options` {Object}
1712-
* `resolution` {number} The sampling rate in milliseconds. Must be greater
1713-
than zero. **Default:** `10`.
1714-
* Returns: {IntervalHistogram}
1716+
* `samplePerIteration` {boolean} When `true`, samples are taken once per
1717+
event loop iteration. **Default:** `false`.
1718+
* `resolution` {number} The sampling rate in milliseconds for interval-based
1719+
sampling. Must be greater than zero. This option is ignored when
1720+
`samplePerIteration` is `true`. **Default:** `10`.
1721+
* Returns: {ELDHistogram}
17151722

17161723
_This property is an extension by Node.js. It is not available in Web browsers._
17171724

1718-
Creates an `IntervalHistogram` object that samples and reports the event loop
1719-
delay over time. The delays will be reported in nanoseconds.
1725+
Creates a histogram object that samples and reports the event loop delay over
1726+
time. The delays will be reported in nanoseconds.
17201727

1721-
Using a timer to detect approximate event loop delay works because the
1722-
execution of timers is tied specifically to the lifecycle of the libuv
1723-
event loop. That is, a delay in the loop will cause a delay in the execution
1724-
of the timer, and those delays are specifically what this API is intended to
1725-
detect.
1728+
By default, the histogram is updated by a timer using the configured
1729+
`resolution`. When `samplePerIteration` is `true`, samples are taken once per
1730+
event loop iteration using `uv_prepare_t` and `uv_check_t` hooks. In that mode,
1731+
the histogram does not keep the loop alive or force additional iterations when
1732+
the application is idle.
1733+
The two sampling modes produce significantly different results and should not
1734+
be compared directly.
17261735

17271736
```mjs
17281737
import { monitorEventLoopDelay } from 'node:perf_hooks';
@@ -1999,9 +2008,10 @@ added: v11.10.0
19992008

20002009
The standard deviation of the recorded event loop delays.
20012010

2002-
## Class: `IntervalHistogram extends Histogram`
2011+
## Class: `ELDHistogram extends Histogram`
20032012

2004-
A `Histogram` that is periodically updated on a given interval.
2013+
A `Histogram` that records event loop delay, returned by
2014+
[`perf_hooks.monitorEventLoopDelay()`][].
20052015

20062016
### `histogram.disable()`
20072017

@@ -2011,7 +2021,7 @@ added: v11.10.0
20112021

20122022
* Returns: {boolean}
20132023

2014-
Disables the update interval timer. Returns `true` if the timer was
2024+
Disables event loop delay sampling. Returns `true` if sampling was
20152025
stopped, `false` if it was already stopped.
20162026

20172027
### `histogram.enable()`
@@ -2022,7 +2032,7 @@ added: v11.10.0
20222032

20232033
* Returns: {boolean}
20242034

2025-
Enables the update interval timer. Returns `true` if the timer was
2035+
Enables event loop delay sampling. Returns `true` if sampling was
20262036
started, `false` if it was already started.
20272037

20282038
### `histogram[Symbol.dispose]()`
@@ -2031,7 +2041,7 @@ started, `false` if it was already started.
20312041
added: v24.2.0
20322042
-->
20332043

2034-
Disables the update interval timer when the histogram is disposed.
2044+
Disables event loop delay sampling when the histogram is disposed.
20352045

20362046
```js
20372047
const { monitorEventLoopDelay } = require('node:perf_hooks');
@@ -2042,11 +2052,11 @@ const { monitorEventLoopDelay } = require('node:perf_hooks');
20422052
}
20432053
```
20442054

2045-
### Cloning an `IntervalHistogram`
2055+
### Cloning an `ELDHistogram`
20462056

2047-
{IntervalHistogram} instances can be cloned via {MessagePort}. On the receiving
2048-
end, the histogram is cloned as a plain {Histogram} object that does not
2049-
implement the `enable()` and `disable()` methods.
2057+
{ELDHistogram} instances can be cloned via {MessagePort}. On the receiving end,
2058+
the histogram is cloned as a plain {Histogram} object that does not implement
2059+
the `enable()` and `disable()` methods.
20502060

20512061
## Class: `RecordableHistogram extends Histogram`
20522062

@@ -2354,6 +2364,7 @@ dns.promises.resolve('localhost');
23542364
[`'exit'`]: process.md#event-exit
23552365
[`child_process.spawnSync()`]: child_process.md#child_processspawnsynccommand-args-options
23562366
[`perf_hooks.eventLoopUtilization()`]: #perf_hookseventlooputilizationutilization1-utilization2
2367+
[`perf_hooks.monitorEventLoopDelay()`]: #perf_hooksmonitoreventloopdelayoptions
23572368
[`perf_hooks.timerify()`]: #perf_hookstimerifyfn-options
23582369
[`process.hrtime()`]: process.md#processhrtimetime
23592370
[`timeOrigin`]: https://w3c.github.io/hr-time/#dom-performance-timeorigin

lib/internal/perf/event_loop_delay.js

Lines changed: 5 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,7 @@ const {
1818
} = internalBinding('performance');
1919

2020
const {
21+
validateBoolean,
2122
validateInteger,
2223
validateObject,
2324
} = require('internal/validators');
@@ -74,21 +75,23 @@ class ELDHistogram extends Histogram {
7475

7576
/**
7677
* @param {{
78+
* samplePerIteration : boolean,
7779
* resolution : number
7880
* }} [options]
7981
* @returns {ELDHistogram}
8082
*/
8183
function monitorEventLoopDelay(options = kEmptyObject) {
8284
validateObject(options, 'options');
8385

84-
const { resolution = 10 } = options;
86+
const { samplePerIteration = false, resolution = 10 } = options;
87+
validateBoolean(samplePerIteration, 'options.samplePerIteration');
8588
validateInteger(resolution, 'options.resolution', 1);
8689

8790
return ReflectConstruct(
8891
function() {
8992
markTransferMode(this, true, false);
9093
this[kEnabled] = false;
91-
this[kHandle] = createELDHistogram(resolution);
94+
this[kHandle] = createELDHistogram(resolution, samplePerIteration);
9295
this[kMap] = new SafeMap();
9396
}, [], ELDHistogram);
9497
}

src/env_properties.h

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -434,6 +434,7 @@
434434
V(http2ping_constructor_template, v8::ObjectTemplate) \
435435
V(i18n_converter_template, v8::ObjectTemplate) \
436436
V(intervalhistogram_constructor_template, v8::FunctionTemplate) \
437+
V(iterationhistogram_constructor_template, v8::FunctionTemplate) \
437438
V(iter_template, v8::DictionaryTemplate) \
438439
V(js_transferable_constructor_template, v8::FunctionTemplate) \
439440
V(libuv_stream_wrap_ctor_template, v8::FunctionTemplate) \

src/histogram.cc

Lines changed: 163 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -25,6 +25,20 @@ using v8::String;
2525
using v8::Uint32;
2626
using v8::Value;
2727

28+
template <typename T>
29+
void StartHandleHistogram(Local<Value> receiver, bool reset) {
30+
T* histogram;
31+
ASSIGN_OR_RETURN_UNWRAP(&histogram, receiver);
32+
histogram->OnStart(reset ? T::StartFlags::RESET : T::StartFlags::NONE);
33+
}
34+
35+
template <typename T>
36+
void StopHandleHistogram(Local<Value> receiver) {
37+
T* histogram;
38+
ASSIGN_OR_RETURN_UNWRAP(&histogram, receiver);
39+
histogram->OnStop();
40+
}
41+
2842
Histogram::Histogram(const Options& options) {
2943
hdr_histogram* histogram;
3044
CHECK_EQ(0, hdr_init(options.lowest,
@@ -68,6 +82,10 @@ CFunction IntervalHistogram::fast_start_(
6882
CFunction::Make(&IntervalHistogram::FastStart));
6983
CFunction IntervalHistogram::fast_stop_(
7084
CFunction::Make(&IntervalHistogram::FastStop));
85+
CFunction IterationHistogram::fast_start_(
86+
CFunction::Make(&IterationHistogram::FastStart));
87+
CFunction IterationHistogram::fast_stop_(
88+
CFunction::Make(&IterationHistogram::FastStop));
7189

7290
void HistogramImpl::AddMethods(Isolate* isolate, Local<FunctionTemplate> tmpl) {
7391
// TODO(@jasnell): The bigint API variations do not yet support fast
@@ -419,29 +437,157 @@ void IntervalHistogram::OnStop() {
419437
}
420438

421439
void IntervalHistogram::Start(const FunctionCallbackInfo<Value>& args) {
422-
IntervalHistogram* histogram;
423-
ASSIGN_OR_RETURN_UNWRAP(&histogram, args.This());
424-
histogram->OnStart(args[0]->IsTrue() ? StartFlags::RESET : StartFlags::NONE);
440+
StartHandleHistogram<IntervalHistogram>(args.This(), args[0]->IsTrue());
425441
}
426442

427443
void IntervalHistogram::FastStart(Local<Value> receiver, bool reset) {
428444
TRACK_V8_FAST_API_CALL("histogram.start");
429-
IntervalHistogram* histogram;
430-
ASSIGN_OR_RETURN_UNWRAP(&histogram, receiver);
431-
histogram->OnStart(reset ? StartFlags::RESET : StartFlags::NONE);
445+
StartHandleHistogram<IntervalHistogram>(receiver, reset);
432446
}
433447

434448
void IntervalHistogram::Stop(const FunctionCallbackInfo<Value>& args) {
435-
IntervalHistogram* histogram;
436-
ASSIGN_OR_RETURN_UNWRAP(&histogram, args.This());
437-
histogram->OnStop();
449+
StopHandleHistogram<IntervalHistogram>(args.This());
438450
}
439451

440452
void IntervalHistogram::FastStop(Local<Value> receiver) {
441453
TRACK_V8_FAST_API_CALL("histogram.stop");
442-
IntervalHistogram* histogram;
443-
ASSIGN_OR_RETURN_UNWRAP(&histogram, receiver);
444-
histogram->OnStop();
454+
StopHandleHistogram<IntervalHistogram>(receiver);
455+
}
456+
457+
Local<FunctionTemplate> IterationHistogram::GetConstructorTemplate(
458+
Environment* env) {
459+
Local<FunctionTemplate> tmpl = env->iterationhistogram_constructor_template();
460+
if (tmpl.IsEmpty()) {
461+
Isolate* isolate = env->isolate();
462+
tmpl = NewFunctionTemplate(isolate, nullptr);
463+
tmpl->Inherit(HandleWrap::GetConstructorTemplate(env));
464+
tmpl->SetClassName(FIXED_ONE_BYTE_STRING(isolate, "Histogram"));
465+
auto instance = tmpl->InstanceTemplate();
466+
instance->SetInternalFieldCount(IterationHistogram::kInternalFieldCount);
467+
HistogramImpl::AddMethods(isolate, tmpl);
468+
SetFastMethod(isolate, instance, "start", Start, &fast_start_);
469+
SetFastMethod(isolate, instance, "stop", Stop, &fast_stop_);
470+
env->set_iterationhistogram_constructor_template(tmpl);
471+
}
472+
return tmpl;
473+
}
474+
475+
void IterationHistogram::RegisterExternalReferences(
476+
ExternalReferenceRegistry* registry) {
477+
registry->Register(Start);
478+
registry->Register(Stop);
479+
registry->Register(fast_start_);
480+
registry->Register(fast_stop_);
481+
HistogramImpl::RegisterExternalReferences(registry);
482+
}
483+
484+
IterationHistogram::IterationHistogram(Environment* env,
485+
Local<Object> wrap,
486+
AsyncWrap::ProviderType type,
487+
const Histogram::Options& options)
488+
: HandleWrap(
489+
env, wrap, reinterpret_cast<uv_handle_t*>(&check_handle_), type),
490+
HistogramImpl(options) {
491+
MakeWeak();
492+
wrap->SetAlignedPointerInInternalField(
493+
HistogramImpl::InternalFields::kImplField,
494+
static_cast<HistogramImpl*>(this),
495+
EmbedderDataTag::kDefault);
496+
uv_check_init(env->event_loop(), &check_handle_);
497+
uv_prepare_init(env->event_loop(), &prepare_handle_);
498+
uv_unref(reinterpret_cast<uv_handle_t*>(&check_handle_));
499+
uv_unref(reinterpret_cast<uv_handle_t*>(&prepare_handle_));
500+
prepare_handle_.data = this;
501+
}
502+
503+
BaseObjectPtr<IterationHistogram> IterationHistogram::Create(
504+
Environment* env, const Histogram::Options& options) {
505+
Local<Object> obj;
506+
if (!GetConstructorTemplate(env)
507+
->InstanceTemplate()
508+
->NewInstance(env->context())
509+
.ToLocal(&obj)) {
510+
return nullptr;
511+
}
512+
513+
return MakeBaseObject<IterationHistogram>(
514+
env, obj, AsyncWrap::PROVIDER_ELDHISTOGRAM, options);
515+
}
516+
517+
void IterationHistogram::PrepareCB(uv_prepare_t* handle) {
518+
IterationHistogram* self = static_cast<IterationHistogram*>(handle->data);
519+
if (!self->enabled_) return;
520+
self->prepare_time_ = uv_hrtime();
521+
self->timeout_ = uv_backend_timeout(handle->loop);
522+
}
523+
524+
void IterationHistogram::CheckCB(uv_check_t* handle) {
525+
IterationHistogram* self =
526+
ContainerOf(&IterationHistogram::check_handle_, handle);
527+
if (!self->enabled_) return;
528+
529+
uint64_t check_time = uv_hrtime();
530+
uint64_t poll_time = check_time - self->prepare_time_;
531+
uint64_t latency = self->prepare_time_ - self->check_time_;
532+
533+
if (self->timeout_ >= 0) {
534+
uint64_t timeout_ns = static_cast<uint64_t>(self->timeout_) * 1000 * 1000;
535+
if (poll_time > timeout_ns) {
536+
latency += poll_time - timeout_ns;
537+
}
538+
}
539+
540+
self->histogram()->Record(latency == 0 ? 1 : latency);
541+
self->check_time_ = check_time;
542+
}
543+
544+
void IterationHistogram::MemoryInfo(MemoryTracker* tracker) const {
545+
tracker->TrackField("histogram", histogram());
546+
}
547+
548+
void IterationHistogram::OnStart(StartFlags flags) {
549+
if (enabled_ || IsHandleClosing()) return;
550+
enabled_ = true;
551+
if (flags == StartFlags::RESET) histogram()->Reset();
552+
check_time_ = uv_hrtime();
553+
prepare_time_ = check_time_;
554+
timeout_ = 0;
555+
uv_check_start(&check_handle_, CheckCB);
556+
uv_prepare_start(&prepare_handle_, PrepareCB);
557+
uv_unref(reinterpret_cast<uv_handle_t*>(&check_handle_));
558+
uv_unref(reinterpret_cast<uv_handle_t*>(&prepare_handle_));
559+
}
560+
561+
void IterationHistogram::OnStop() {
562+
if (!enabled_ || IsHandleClosing()) return;
563+
enabled_ = false;
564+
uv_check_stop(&check_handle_);
565+
uv_prepare_stop(&prepare_handle_);
566+
}
567+
568+
void IterationHistogram::Close(Local<Value> close_callback) {
569+
if (IsHandleClosing()) return;
570+
OnStop();
571+
HandleWrap::Close(close_callback);
572+
uv_close(reinterpret_cast<uv_handle_t*>(&prepare_handle_), nullptr);
573+
}
574+
575+
void IterationHistogram::Start(const FunctionCallbackInfo<Value>& args) {
576+
StartHandleHistogram<IterationHistogram>(args.This(), args[0]->IsTrue());
577+
}
578+
579+
void IterationHistogram::FastStart(Local<Value> receiver, bool reset) {
580+
TRACK_V8_FAST_API_CALL("histogram.eventLoopDelay.start");
581+
StartHandleHistogram<IterationHistogram>(receiver, reset);
582+
}
583+
584+
void IterationHistogram::Stop(const FunctionCallbackInfo<Value>& args) {
585+
StopHandleHistogram<IterationHistogram>(args.This());
586+
}
587+
588+
void IterationHistogram::FastStop(Local<Value> receiver) {
589+
TRACK_V8_FAST_API_CALL("histogram.eventLoopDelay.stop");
590+
StopHandleHistogram<IterationHistogram>(receiver);
445591
}
446592

447593
void HistogramImpl::GetCount(const FunctionCallbackInfo<Value>& args) {
@@ -607,6 +753,11 @@ HistogramImpl* HistogramImpl::FromJSObject(Local<Value> value) {
607753
HistogramImpl::kImplField, EmbedderDataTag::kDefault));
608754
}
609755

756+
std::unique_ptr<worker::TransferData> IterationHistogram::CloneForMessaging()
757+
const {
758+
return std::make_unique<HistogramBase::HistogramTransferData>(histogram());
759+
}
760+
610761
std::unique_ptr<worker::TransferData>
611762
IntervalHistogram::CloneForMessaging() const {
612763
return std::make_unique<HistogramBase::HistogramTransferData>(histogram());

0 commit comments

Comments
 (0)