Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

perf_hooks: precise mode for monitorEventLoopDelay #32018

Closed
Closed
Changes from 6 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
24 changes: 17 additions & 7 deletions doc/api/perf_hooks.md
Original file line number Diff line number Diff line change
@@ -432,21 +432,31 @@ is equal to `type`.
## `perf_hooks.monitorEventLoopDelay([options])`
<!-- YAML
added: v11.10.0
changes:
- version: REPLACEME
pr-url: https://github.com/nodejs/node/pull/32018
description: Introduce precise mode (`resolution` equal to `0`). Change
the default `resolution` to `0`.
-->

* `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`.
indutny marked this conversation as resolved.
Show resolved Hide resolved
* 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.
indutny marked this conversation as resolved.
Show resolved Hide resolved

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.
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should we give hints about pros/conts of the two variants? I don't think that it is obvious to someone who isn't that familiar with the inner working of the event loop.

indutny marked this conversation as resolved.
Show resolved Hide resolved

```js
const { monitorEventLoopDelay } = require('perf_hooks');
4 changes: 2 additions & 2 deletions lib/perf_hooks.js
Original file line number Diff line number Diff line change
@@ -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;
jasnell marked this conversation as resolved.
Show resolved Hide resolved
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));
125 changes: 104 additions & 21 deletions src/node_perf.cc
Original file line number Diff line number Diff line change
@@ -474,7 +474,7 @@ static void ELDHistogramNew(const FunctionCallbackInfo<Value>& 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);
indutny marked this conversation as resolved.
Show resolved Hide resolved

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<Value> 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<uv_handle_t*>(&prepare_), nullptr);
uv_close(reinterpret_cast<uv_handle_t*>(&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;
}
Comment on lines +567 to +569
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Super minor nit... as of late we've been moving away from { }'s for single line ifs.

Suggested change
if (prev_ == 0) {
return;
}
if (prev_ == 0)
return;

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is it part of official code style for Node.js? make lint didn't catch this.

If there any way to persuade, I'd insist that we keep parens even though (as many of you certainly know and remember) I was a proponent of omitting them. That apple kernel bug that was fixed some time ago has convinced me that omitting parens is error prone. I don't have a link to the kernel fix anymore, but it looked like this:

if (something)
if (something_else)
  do_something();

Forgetting to put an if body would result it in compiler interpreting the code in likely undesirable way.

That being said, I don't insist on changing existing code. Still it'd be great to write new code differently!


uint64_t time = uv_hrtime();
int64_t delta = time - prev_;
if (delta <= 0) {
return;
}
Comment on lines +573 to +575
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit...

Suggested change
if (delta <= 0) {
return;
}
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_++;
}
Comment on lines +579 to +584
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit...

Suggested change
if (ret) {
return;
}
if (exceeds_ < 0xFFFFFFFF) {
exceeds_++;
}
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<uv_handle_t*>(&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<uv_handle_t*>(&prepare_));
uv_unref(reinterpret_cast<uv_handle_t*>(&check_));
} else {
CHECK_EQ(uv_timer_start(&timer_,
DelayIntervalCallback,
resolution_,
resolution_),
0);
uv_unref(reinterpret_cast<uv_handle_t*>(&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;
}

15 changes: 14 additions & 1 deletion src/node_perf.h
Original file line number Diff line number Diff line change
@@ -153,7 +153,10 @@ class ELDHistogram : public HandleWrap, public Histogram {
Local<Object> 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<Value> close_callback = Local<Value>()) 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_;
addaleax marked this conversation as resolved.
Show resolved Hide resolved
};

} // namespace performance
6 changes: 3 additions & 3 deletions test/sequential/test-performance-eventloopdelay.js
Original file line number Diff line number Diff line change
@@ -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() {