Skip to content

Commit e5cc439

Browse files
committed
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 aecae97 commit e5cc439

9 files changed

Lines changed: 411 additions & 35 deletions

File tree

doc/api/perf_hooks.md

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

17021702
<!-- YAML
17031703
added: v11.10.0
1704+
changes:
1705+
- version: REPLACEME
1706+
pr-url: https://github.com/nodejs/node/pull/62935
1707+
description: Added the `samplePerIteration` option.
17041708
-->
17051709

17061710
* `options` {Object}
1707-
* `resolution` {number} The sampling rate in milliseconds. Must be greater
1708-
than zero. **Default:** `10`.
1709-
* Returns: {IntervalHistogram}
1711+
* `samplePerIteration` {boolean} When `true`, samples are taken once per
1712+
event loop iteration. **Default:** `false`.
1713+
* `resolution` {number} The sampling rate in milliseconds for interval-based
1714+
sampling. Must be greater than zero. This option is ignored when
1715+
`samplePerIteration` is `true`. **Default:** `10`.
1716+
* Returns: {ELDHistogram}
17101717

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

1713-
Creates an `IntervalHistogram` object that samples and reports the event loop
1714-
delay over time. The delays will be reported in nanoseconds.
1720+
Creates a histogram object that samples and reports the event loop delay over
1721+
time. The delays will be reported in nanoseconds.
17151722

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

17221731
```mjs
17231732
import { monitorEventLoopDelay } from 'node:perf_hooks';
@@ -1992,9 +2001,10 @@ added: v11.10.0
19922001

19932002
The standard deviation of the recorded event loop delays.
19942003

1995-
## Class: `IntervalHistogram extends Histogram`
2004+
## Class: `ELDHistogram extends Histogram`
19962005

1997-
A `Histogram` that is periodically updated on a given interval.
2006+
A `Histogram` that records event loop delay, returned by
2007+
[`perf_hooks.monitorEventLoopDelay()`][].
19982008

19992009
### `histogram.disable()`
20002010

@@ -2004,7 +2014,7 @@ added: v11.10.0
20042014

20052015
* Returns: {boolean}
20062016

2007-
Disables the update interval timer. Returns `true` if the timer was
2017+
Disables event loop delay sampling. Returns `true` if sampling was
20082018
stopped, `false` if it was already stopped.
20092019

20102020
### `histogram.enable()`
@@ -2015,7 +2025,7 @@ added: v11.10.0
20152025

20162026
* Returns: {boolean}
20172027

2018-
Enables the update interval timer. Returns `true` if the timer was
2028+
Enables event loop delay sampling. Returns `true` if sampling was
20192029
started, `false` if it was already started.
20202030

20212031
### `histogram[Symbol.dispose]()`
@@ -2024,7 +2034,7 @@ started, `false` if it was already started.
20242034
added: v24.2.0
20252035
-->
20262036

2027-
Disables the update interval timer when the histogram is disposed.
2037+
Disables event loop delay sampling when the histogram is disposed.
20282038

20292039
```js
20302040
const { monitorEventLoopDelay } = require('node:perf_hooks');
@@ -2035,11 +2045,11 @@ const { monitorEventLoopDelay } = require('node:perf_hooks');
20352045
}
20362046
```
20372047

2038-
### Cloning an `IntervalHistogram`
2048+
### Cloning an `ELDHistogram`
20392049

2040-
{IntervalHistogram} instances can be cloned via {MessagePort}. On the receiving
2041-
end, the histogram is cloned as a plain {Histogram} object that does not
2042-
implement the `enable()` and `disable()` methods.
2050+
{ELDHistogram} instances can be cloned via {MessagePort}. On the receiving end,
2051+
the histogram is cloned as a plain {Histogram} object that does not implement
2052+
the `enable()` and `disable()` methods.
20432053

20442054
## Class: `RecordableHistogram extends Histogram`
20452055

@@ -2352,6 +2362,7 @@ dns.promises.resolve('localhost');
23522362
[`'exit'`]: process.md#event-exit
23532363
[`child_process.spawnSync()`]: child_process.md#child_processspawnsynccommand-args-options
23542364
[`perf_hooks.eventLoopUtilization()`]: #perf_hookseventlooputilizationutilization1-utilization2
2365+
[`perf_hooks.monitorEventLoopDelay()`]: #perf_hooksmonitoreventloopdelayoptions
23552366
[`perf_hooks.timerify()`]: #perf_hookstimerifyfn-options
23562367
[`process.hrtime()`]: process.md#processhrtimetime
23572368
[`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
@@ -418,6 +418,7 @@
418418
V(http2ping_constructor_template, v8::ObjectTemplate) \
419419
V(i18n_converter_template, v8::ObjectTemplate) \
420420
V(intervalhistogram_constructor_template, v8::FunctionTemplate) \
421+
V(iterationhistogram_constructor_template, v8::FunctionTemplate) \
421422
V(iter_template, v8::DictionaryTemplate) \
422423
V(js_transferable_constructor_template, v8::FunctionTemplate) \
423424
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
@@ -416,29 +434,157 @@ void IntervalHistogram::OnStop() {
416434
}
417435

418436
void IntervalHistogram::Start(const FunctionCallbackInfo<Value>& args) {
419-
IntervalHistogram* histogram;
420-
ASSIGN_OR_RETURN_UNWRAP(&histogram, args.This());
421-
histogram->OnStart(args[0]->IsTrue() ? StartFlags::RESET : StartFlags::NONE);
437+
StartHandleHistogram<IntervalHistogram>(args.This(), args[0]->IsTrue());
422438
}
423439

424440
void IntervalHistogram::FastStart(Local<Value> receiver, bool reset) {
425441
TRACK_V8_FAST_API_CALL("histogram.start");
426-
IntervalHistogram* histogram;
427-
ASSIGN_OR_RETURN_UNWRAP(&histogram, receiver);
428-
histogram->OnStart(reset ? StartFlags::RESET : StartFlags::NONE);
442+
StartHandleHistogram<IntervalHistogram>(receiver, reset);
429443
}
430444

431445
void IntervalHistogram::Stop(const FunctionCallbackInfo<Value>& args) {
432-
IntervalHistogram* histogram;
433-
ASSIGN_OR_RETURN_UNWRAP(&histogram, args.This());
434-
histogram->OnStop();
446+
StopHandleHistogram<IntervalHistogram>(args.This());
435447
}
436448

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

444590
void HistogramImpl::GetCount(const FunctionCallbackInfo<Value>& args) {
@@ -604,6 +750,11 @@ HistogramImpl* HistogramImpl::FromJSObject(Local<Value> value) {
604750
obj->GetAlignedPointerFromInternalField(HistogramImpl::kImplField));
605751
}
606752

753+
std::unique_ptr<worker::TransferData> IterationHistogram::CloneForMessaging()
754+
const {
755+
return std::make_unique<HistogramBase::HistogramTransferData>(histogram());
756+
}
757+
607758
std::unique_ptr<worker::TransferData>
608759
IntervalHistogram::CloneForMessaging() const {
609760
return std::make_unique<HistogramBase::HistogramTransferData>(histogram());

0 commit comments

Comments
 (0)