perf_hooks: precise mode for monitorEventLoopDelay #32018

indutny · 2020-02-29T05:09:38Z

Introduce precise mode of monitorEventLoopDelay by using uv_check_t
and uv_prepare_t instead of uv_timer_t.

Checklist

make -j4 test (UNIX), or vcbuild test (Windows) passes
tests and/or benchmarks are included
documentation is changed or added
commit message follows commit guidelines

NOTE: Updated the title and description of the issue on 2020-02-29

indutny · 2020-02-29T05:09:55Z

@nodejs/performance

doc/api/perf_hooks.md

src/node_perf.h

mcollina

lgtm, it would be good to check how much overhead this adds compared to the timer approach.

Flarna · 2020-02-29T23:51:37Z

Should we mentions somewhere that the actual numbers returned change? Before this PR they were biased by the resolution (e.g. a 10 ms timer but no extra delay resulted in 10ms), now the bias is 0 (which is a good thing in my opinion).

I notices that the result looks not that nice if nothing happens between enable and disable but I think this is not caused by this PR. Most likely use of uninitialized variable or similar:

min: 9223372036854.775
max: 0
mean: NaN
stddev: NaN

indutny · 2020-03-01T01:22:59Z

@Flarna good point! This is indeed the case.

Another important change of behavior to consider: the timer was adding the data to histogram even without any event loop activity. With my change the data is emitted only when event loop delay actually happens.

I can see how timer might be useful for reporting since histogram only reports aggregates. Do we care about this behavior change? Is it desirable?

jasnell · 2020-03-01T03:55:14Z

I'd hate to say it because it makes the implementation more complicated but I actually think having both available would be awesome. I.e. If resolution is provided, use the timer, if not, use the new semantics.

jasnell · 2020-03-01T04:16:01Z

Most likely use of uninitialized variable or similar:

min: 9223372036854.775
max: 0
mean: NaN
stddev: NaN

Nope, this is intentional. The min is the max value for the field so that comparison with the original value to find the new minimum always works. Likewise for the max being zero so that comparisons to find the new max always work. The NaN's are indications that no data has been collected yet.

indutny · 2020-03-01T06:09:44Z

I'd hate to say it because it makes the implementation more complicated but I actually think having both available would be awesome. I.e. If resolution is provided, use the timer, if not, use the new semantics.

This is a very good proposal. I'll give it a try.

Introduce precise mode of `monitorEventLoopDelay` by using `uv_check_t` and `uv_prepare_t` instead of `uv_timer_t`.

indutny · 2020-03-01T07:37:24Z

@jsanell it is done

Flarna · 2020-03-01T11:38:04Z

Nope, this is intentional. The min is the max value for the field so that comparison with the original value to find the new minimum always works. Likewise for the max being zero so that comparisons to find the new max always work. The NaN's are indications that no data has been collected yet.

@jasnell I understand this from implementation point of view but not regarding presenting the result to the user. Users don't have to do such comparsions. Anyhow it's not related to this PR.

src/node_perf.cc

Flarna · 2020-03-01T11:54:35Z

doc/api/perf_hooks.md

+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.


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.

doc/api/perf_hooks.md

Co-Authored-By: Anna Henningsen <github@addaleax.net>

Flarna · 2020-03-02T07:37:31Z

Please note that even after the change to combine the two implementations the behavior has changed in case no argument is given - it is and was optional.
To workaround this it would be possible to add e.g a boolean precise to options to move to the precise measurement.

Personally I see no advantage of the timer variant. At least on windows timers are quite imprecise in case event look is idle. And honestly speaking who cares about event loop delay for an idle nodejs process?

Don't get me wrong here, I don't want to block this.

Edit: I found that my above statement is wrong, it still defaults to the 10ms timerbased approach. To get to the new { resolution: 0 } needs to be specified.

doc/api/perf_hooks.md

lib/perf_hooks.js

jasnell · 2020-03-02T19:03:00Z

Just an FYI #31988 has landed

doc/api/perf_hooks.md

jasnell · 2020-03-03T00:32:50Z

src/node_perf.cc

+  if (prev_ == 0) {
+    return;
+  }


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;

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!

jasnell · 2020-03-03T00:33:33Z

src/node_perf.cc

+  if (delta <= 0) {
+    return;
+  }


nit...

Suggested change

if (delta <= 0) {

return;

}

if (delta <= 0)

return;

jasnell · 2020-03-03T00:33:59Z

src/node_perf.cc

+  if (ret) {
+    return;
+  }
+  if (exceeds_ < 0xFFFFFFFF) {
+    exceeds_++;
+  }


nit...

Suggested change

if (ret) {

return;

}

if (exceeds_ < 0xFFFFFFFF) {

exceeds_++;

}

if (ret)

return;

if (exceeds_ < 0xFFFFFFFF)

exceeds_++;

trevnorris · 2020-03-03T21:21:58Z

Hey. After seeing this I sped up a PR I'd been planning to collect idle time in the kernel's event provider. I've posted it here: libuv/libuv#2725

I think it'll be helpful to take a look before landing this.

Co-Authored-By: Sam Roberts <vieuxtech@gmail.com>

indutny · 2020-03-04T21:36:42Z

Would changing the default value constitute a major version change or can it be released as minor? @nodejs/releasers (<- not sure if it is the right group)

indutny · 2020-03-04T22:39:54Z

This is embarrassing, but after a conversation with @trevnorris I have to close this PR. I forgot that even though uv_prepare_t callback is invoked before uv__io_poll and uv_check_t right after it, uv__io_poll itself invokes the user callbacks... The only thing that this PR measures in its current form is the busy time of timers and setImmediate callbacks...

indutny · 2020-03-04T22:40:03Z

Sorry again y'all...

jasnell · 2020-03-04T22:42:37Z

I forgot that even though uv_prepare_t callback is invoked before uv__io_poll and uv_check_t right after it, uv__io_poll itself invokes the user callbacks.

Doh!! That's right. Don't feel bad because I forgot that also ;)

indutny · 2020-03-04T22:50:11Z

@jasnell funny, but I think I've found a solution. The idea is to measure the time between uv_check_t calls just like current version measures the time between uv_timer_t calls. Will experiment and test it before asking you to review it again!

indutny · 2020-03-05T04:32:04Z

Sorry, but I had to open a new Pull Request: #32102 . GitHub won't let me reopen this one after the force push (what a surprise!)

joshxyzhimself · 2020-05-18T11:20:33Z

Hi, quite off-topic questions but

1.) Does monitorEventLoopDelay create performance impacts if kept running?
2.) The Histogram instance returned has a reset function, does it mean that it's accumulating an amount of data in the backround which needs to be reset in every interval? And if so, I'm assuming the amount of data is affected by the resolution parameter?
3.) Are there any ideal ranges for the resolution parameter? Does using 100 ms or 500 ms for resolution parameter still makes sense?

jasnell · 2020-05-18T12:56:50Z

1.) Does monitorEventLoopDelay create performance impacts if kept running?

It should be minimal. The monitor creates a libuv timer that triggers based on the resolution. The perf impact should be negligible.

2.) The Histogram instance returned has a reset function, does it mean that it's accumulating an amount of data in the backround which needs to be reset in every interval? And if so, I'm assuming the amount of data is affected by the resolution parameter?

Again, very minimal. You can see the definition of the underlying Histogram here. The amount of data stored really depends on the number of histogram buckets used but even that will be negligible. The longer the histogram runs, the more fixed it's approximate memory use should become. The reset is more about giving more control over data collection than memory management.

3.) Are there any ideal ranges for the resolution parameter? Does using 100 ms or 500 ms for resolution parameter still makes sense?

That's going to depend on your workload. Because it is using a timer for execution, which allows the event loop to turn in between calls, setting a high resolution makes is more likely that you will miss relevant samples. What I would do is profile your application to figure out what your typical event loop blocking range is under load and determine a resolution that catches the minimum of that range and higher.

indutny requested review from jasnell and addaleax February 29, 2020 05:09

nodejs-github-bot added c++ Issues and PRs that require attention from people who are familiar with C++. perf_hooks Issues and PRs related to the implementation of the Performance Timing API. labels Feb 29, 2020

indutny mentioned this pull request Feb 29, 2020

perf_hooks: introduce monitorEventLoopIdleness #31992

Closed

4 tasks

addaleax approved these changes Feb 29, 2020

View reviewed changes

doc/api/perf_hooks.md Outdated Show resolved Hide resolved

src/node_perf.h Show resolved Hide resolved

indutny requested a review from bnoordhuis February 29, 2020 06:19

mcollina approved these changes Feb 29, 2020

View reviewed changes

cjihrig approved these changes Feb 29, 2020

View reviewed changes

devnexen approved these changes Feb 29, 2020

View reviewed changes

perf_hooks: precise mode for monitorEventLoopDelay

334af98

Introduce precise mode of `monitorEventLoopDelay` by using `uv_check_t` and `uv_prepare_t` instead of `uv_timer_t`.

indutny force-pushed the feature/simplify-eventloopdelay branch from a3eb955 to 334af98 Compare March 1, 2020 07:36

indutny changed the title ~~perf_hooks: simplify monitorEventLoopDelay~~ perf_hooks: precise mode for monitorEventLoopDelay Mar 1, 2020

indutny added 2 commits February 29, 2020 23:38

doc: minor fix

31da304

src: style fix

6685c7e

Flarna reviewed Mar 1, 2020

View reviewed changes

src/node_perf.cc Show resolved Hide resolved

Flarna reviewed Mar 1, 2020

View reviewed changes

addaleax approved these changes Mar 1, 2020

View reviewed changes

doc/api/perf_hooks.md Outdated Show resolved Hide resolved

indutny and others added 2 commits March 1, 2020 07:08

Update doc/api/perf_hooks.md

ae29599

Co-Authored-By: Anna Henningsen <github@addaleax.net>

src: add comment

6ef15b7

Flarna approved these changes Mar 1, 2020

View reviewed changes

jasnell approved these changes Mar 1, 2020

View reviewed changes

starkwang approved these changes Mar 2, 2020

View reviewed changes

Flarna reviewed Mar 2, 2020

View reviewed changes

doc/api/perf_hooks.md Show resolved Hide resolved

perf_hooks: update default

4e8a342

jasnell reviewed Mar 2, 2020

View reviewed changes

lib/perf_hooks.js Show resolved Hide resolved

sam-github approved these changes Mar 2, 2020

View reviewed changes

doc/api/perf_hooks.md Outdated Show resolved Hide resolved

doc/api/perf_hooks.md Outdated Show resolved Hide resolved

sam-github mentioned this pull request Mar 2, 2020

feat: implement advanced event loop monitoring siimon/prom-client#278

Merged

jasnell reviewed Mar 3, 2020

View reviewed changes

trevnorris mentioned this pull request Mar 3, 2020

Add API for measuring event loop idle time libuv/libuv#2725

Merged

indutny and others added 2 commits March 4, 2020 13:28

Update doc/api/perf_hooks.md

fa5c98e

Co-Authored-By: Sam Roberts <vieuxtech@gmail.com>

Update doc/api/perf_hooks.md

5fbad01

Co-Authored-By: Sam Roberts <vieuxtech@gmail.com>

docs: lint

2a211b2

indutny closed this Mar 4, 2020

indutny mentioned this pull request Mar 5, 2020

perf_hooks: precise mode for monitorEventLoopDelay #32102

Closed

4 tasks

ChristianBoehlke mentioned this pull request May 4, 2020

Improve Event Loop Lag Metric siimon/prom-client#370

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

perf_hooks: precise mode for monitorEventLoopDelay #32018

perf_hooks: precise mode for monitorEventLoopDelay #32018

indutny commented Feb 29, 2020 •

edited

Loading

indutny commented Feb 29, 2020

mcollina left a comment

Flarna commented Feb 29, 2020

indutny commented Mar 1, 2020

jasnell commented Mar 1, 2020

jasnell commented Mar 1, 2020

indutny commented Mar 1, 2020

indutny commented Mar 1, 2020

Flarna commented Mar 1, 2020

Flarna Mar 1, 2020

Flarna commented Mar 2, 2020 •

edited

Loading

jasnell commented Mar 2, 2020

jasnell Mar 3, 2020

indutny Mar 4, 2020

jasnell Mar 3, 2020

jasnell Mar 3, 2020

trevnorris commented Mar 3, 2020

indutny commented Mar 4, 2020

indutny commented Mar 4, 2020

indutny commented Mar 4, 2020

jasnell commented Mar 4, 2020

indutny commented Mar 4, 2020

indutny commented Mar 5, 2020

joshxyzhimself commented May 18, 2020

jasnell commented May 18, 2020

perf_hooks: precise mode for monitorEventLoopDelay #32018

perf_hooks: precise mode for monitorEventLoopDelay #32018

Conversation

indutny commented Feb 29, 2020 • edited Loading

Checklist

indutny commented Feb 29, 2020

mcollina left a comment

Choose a reason for hiding this comment

Flarna commented Feb 29, 2020

indutny commented Mar 1, 2020

jasnell commented Mar 1, 2020

jasnell commented Mar 1, 2020

indutny commented Mar 1, 2020

indutny commented Mar 1, 2020

Flarna commented Mar 1, 2020

Flarna Mar 1, 2020

Choose a reason for hiding this comment

Flarna commented Mar 2, 2020 • edited Loading

jasnell commented Mar 2, 2020

jasnell Mar 3, 2020

Choose a reason for hiding this comment

indutny Mar 4, 2020

Choose a reason for hiding this comment

jasnell Mar 3, 2020

Choose a reason for hiding this comment

jasnell Mar 3, 2020

Choose a reason for hiding this comment

trevnorris commented Mar 3, 2020

indutny commented Mar 4, 2020

indutny commented Mar 4, 2020

indutny commented Mar 4, 2020

jasnell commented Mar 4, 2020

indutny commented Mar 4, 2020

indutny commented Mar 5, 2020

joshxyzhimself commented May 18, 2020

jasnell commented May 18, 2020

indutny commented Feb 29, 2020 •

edited

Loading

Flarna commented Mar 2, 2020 •

edited

Loading