Skip to content

Commit 70ebe66

Browse files
pabloerhardaduh95
pabloerhard
authored and
aduh95
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 <[email protected]> PR-URL: #62935 Backport-PR-URL: #64480 Reviewed-By: Antoine du Hamel <[email protected]>
1 parent f67161c commit 70ebe66

9 files changed

Lines changed: 410 additions & 35 deletions

File tree

‎doc/api/perf_hooks.md‎

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

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

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

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

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

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

17211730
```mjs
17221731
import { monitorEventLoopDelay } from 'node:perf_hooks';
@@ -1991,9 +2000,10 @@ added: v11.10.0
19912000

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

1994-
## Class: `IntervalHistogram extends Histogram`
2003+
## Class: `ELDHistogram extends Histogram`
19952004

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

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

@@ -2003,7 +2013,7 @@ added: v11.10.0
20032013

20042014
* Returns: {boolean}
20052015

2006-
Disables the update interval timer. Returns `true` if the timer was
2016+
Disables event loop delay sampling. Returns `true` if sampling was
20072017
stopped, `false` if it was already stopped.
20082018

20092019
### `histogram.enable()`
@@ -2014,7 +2024,7 @@ added: v11.10.0
20142024

20152025
* Returns: {boolean}
20162026

2017-
Enables the update interval timer. Returns `true` if the timer was
2027+
Enables event loop delay sampling. Returns `true` if sampling was
20182028
started, `false` if it was already started.
20192029

20202030
### `histogram[Symbol.dispose]()`
@@ -2023,7 +2033,7 @@ started, `false` if it was already started.
20232033
added: v24.2.0
20242034
-->
20252035

2026-
Disables the update interval timer when the histogram is disposed.
2036+
Disables event loop delay sampling when the histogram is disposed.
20272037

20282038
```js
20292039
const { monitorEventLoopDelay } = require('node:perf_hooks');
@@ -2034,11 +2044,11 @@ const { monitorEventLoopDelay } = require('node:perf_hooks');
20342044
}
20352045
```
20362046

2037-
### Cloning an `IntervalHistogram`
2047+
### Cloning an `ELDHistogram`
20382048

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

20432053
## Class: `RecordableHistogram extends Histogram`
20442054

@@ -2346,6 +2356,7 @@ dns.promises.resolve('localhost');
23462356
[`'exit'`]: process.md#event-exit
23472357
[`child_process.spawnSync()`]: child_process.md#child_processspawnsynccommand-args-options
23482358
[`perf_hooks.eventLoopUtilization()`]: #perf_hookseventlooputilizationutilization1-utilization2
2359+
[`perf_hooks.monitorEventLoopDelay()`]: #perf_hooksmonitoreventloopdelayoptions
23492360
[`perf_hooks.timerify()`]: #perf_hookstimerifyfn-options
23502361
[`process.hrtime()`]: process.md#processhrtimetime
23512362
[`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: 162 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,156 @@ 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+
uv_check_init(env->event_loop(), &check_handle_);
493+
uv_prepare_init(env->event_loop(), &prepare_handle_);
494+
uv_unref(reinterpret_cast<uv_handle_t*>(&check_handle_));
495+
uv_unref(reinterpret_cast<uv_handle_t*>(&prepare_handle_));
496+
prepare_handle_.data = this;
497+
}
498+
499+
BaseObjectPtr<IterationHistogram> IterationHistogram::Create(
500+
Environment* env, const Histogram::Options& options) {
501+
Local<Object> obj;
502+
if (!GetConstructorTemplate(env)
503+
->InstanceTemplate()
504+
->NewInstance(env->context())
505+
.ToLocal(&obj)) {
506+
return nullptr;
507+
}
508+
509+
return MakeBaseObject<IterationHistogram>(
510+
env, obj, AsyncWrap::PROVIDER_ELDHISTOGRAM, options);
511+
}
512+
513+
void IterationHistogram::PrepareCB(uv_prepare_t* handle) {
514+
IterationHistogram* self = static_cast<IterationHistogram*>(handle->data);
515+
if (!self->enabled_) return;
516+
self->prepare_time_ = uv_hrtime();
517+
self->timeout_ = uv_backend_timeout(handle->loop);
518+
}
519+
520+
void IterationHistogram::CheckCB(uv_check_t* handle) {
521+
IterationHistogram* self =
522+
ContainerOf(&IterationHistogram::check_handle_, handle);
523+
if (!self->enabled_) return;
524+
525+
uint64_t check_time = uv_hrtime();
526+
uint64_t poll_time = check_time - self->prepare_time_;
527+
uint64_t latency = self->prepare_time_ - self->check_time_;
528+
529+
if (self->timeout_ >= 0) {
530+
uint64_t timeout_ns = static_cast<uint64_t>(self->timeout_) * 1000 * 1000;
531+
if (poll_time > timeout_ns) {
532+
latency += poll_time - timeout_ns;
533+
}
534+
}
535+
536+
self->histogram()->Record(latency == 0 ? 1 : latency);
537+
self->check_time_ = check_time;
538+
}
539+
540+
void IterationHistogram::MemoryInfo(MemoryTracker* tracker) const {
541+
tracker->TrackField("histogram", histogram());
542+
}
543+
544+
void IterationHistogram::OnStart(StartFlags flags) {
545+
if (enabled_ || IsHandleClosing()) return;
546+
enabled_ = true;
547+
if (flags == StartFlags::RESET) histogram()->Reset();
548+
check_time_ = uv_hrtime();
549+
prepare_time_ = check_time_;
550+
timeout_ = 0;
551+
uv_check_start(&check_handle_, CheckCB);
552+
uv_prepare_start(&prepare_handle_, PrepareCB);
553+
uv_unref(reinterpret_cast<uv_handle_t*>(&check_handle_));
554+
uv_unref(reinterpret_cast<uv_handle_t*>(&prepare_handle_));
555+
}
556+
557+
void IterationHistogram::OnStop() {
558+
if (!enabled_ || IsHandleClosing()) return;
559+
enabled_ = false;
560+
uv_check_stop(&check_handle_);
561+
uv_prepare_stop(&prepare_handle_);
562+
}
563+
564+
void IterationHistogram::Close(Local<Value> close_callback) {
565+
if (IsHandleClosing()) return;
566+
OnStop();
567+
HandleWrap::Close(close_callback);
568+
uv_close(reinterpret_cast<uv_handle_t*>(&prepare_handle_), nullptr);
569+
}
570+
571+
void IterationHistogram::Start(const FunctionCallbackInfo<Value>& args) {
572+
StartHandleHistogram<IterationHistogram>(args.This(), args[0]->IsTrue());
573+
}
574+
575+
void IterationHistogram::FastStart(Local<Value> receiver, bool reset) {
576+
TRACK_V8_FAST_API_CALL("histogram.eventLoopDelay.start");
577+
StartHandleHistogram<IterationHistogram>(receiver, reset);
578+
}
579+
580+
void IterationHistogram::Stop(const FunctionCallbackInfo<Value>& args) {
581+
StopHandleHistogram<IterationHistogram>(args.This());
582+
}
583+
584+
void IterationHistogram::FastStop(Local<Value> receiver) {
585+
TRACK_V8_FAST_API_CALL("histogram.eventLoopDelay.stop");
586+
StopHandleHistogram<IterationHistogram>(receiver);
442587
}
443588

444589
void HistogramImpl::GetCount(const FunctionCallbackInfo<Value>& args) {
@@ -604,6 +749,11 @@ HistogramImpl* HistogramImpl::FromJSObject(Local<Value> value) {
604749
obj->GetAlignedPointerFromInternalField(HistogramImpl::kImplField));
605750
}
606751

752+
std::unique_ptr<worker::TransferData> IterationHistogram::CloneForMessaging()
753+
const {
754+
return std::make_unique<HistogramBase::HistogramTransferData>(histogram());
755+
}
756+
607757
std::unique_ptr<worker::TransferData>
608758
IntervalHistogram::CloneForMessaging() const {
609759
return std::make_unique<HistogramBase::HistogramTransferData>(histogram());

0 commit comments

Comments
 (0)