perf_hooks: add ReqWrap latency monitoring #26556

jasnell · 2019-03-10T01:27:19Z

Similar to the recently added event loop relay, this adds a perf_hooks.monitorRequestWrapLatency() API that tracks the length of time between dispatching a ReqWrap and when the callback is invoked. This effectively tracks how long libuv is taking to perform requested actions. No differentiation is made between types of actions. The idea here is to provide a pulse on the general health of the application. If the histogram skews high, then it's taking libuv a longer time to process individual requests.

const { monitorRequestWrapLatency } = require('perf_hooks');
const m = monitorRequestWrapLatency();
m.enable();
// Do stuff
m.disable();

console.log(m.min);
console.log(m.max);
console.log(m.mean);
console.log(m.stddev);
console.log(m.percentile(50));
console.log(m.percentile(99));
console.log(m.percentiles);  // Map

Also outputs histogram data to the trace event log.

/cc @mcollina @mafintosh @nodejs/diagnostics

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

nodejs-github-bot · 2019-03-10T01:27:21Z

@jasnell build started: https://ci.nodejs.org/blue/organizations/jenkins/node-test-pull-request-lite-pipeline/detail/node-test-pull-request-lite-pipeline/2843/pipeline

mcollina

LGTM

doc/api/perf_hooks.md

src/node_perf.cc

doc/api/tracing.md

BridgeAR · 2019-03-10T13:35:06Z

CI https://ci.nodejs.org/job/node-test-pull-request/21393/

jasnell · 2019-03-10T14:07:34Z

Heh. Looks like ci was a bust ;) will review those today

doc/api/tracing.md

doc/api/perf_hooks.md

vsemozhetbyt · 2019-03-10T15:41:06Z

Is the omission of resolution option intended for this method. in other respects similar to the perf_hooks.monitorEventLoopDelay([options]) method?

jasnell · 2019-03-10T15:55:33Z

Yes, there is no resolution because this monitor is not timer or sampling based. Once enabled, it's on for all ReqWrap instances

src/node_perf.cc

Flarna · 2019-03-11T08:04:54Z

I think it would be nice to include the number of measurements done into the resulting histogram.

lib/perf_hooks.js

doc/api/perf_hooks.md

jasnell · 2019-03-11T20:07:42Z

CI: https://ci.nodejs.org/job/node-test-pull-request/21439/

jasnell · 2019-03-11T22:32:12Z

New CI: https://ci.nodejs.org/job/node-test-pull-request/21442/

jasnell · 2019-03-12T02:25:46Z

@Flarna @BridgeAR ... ok, please take a look. I update the API to accept a list of AsyncWrap provider types that the histogram will keep track of. Multiple monitors can be created and enabled independently of one another to watch for different combinations of things.

doc/api/perf_hooks.md

src/node_perf.h

src/node_perf.cc

Flarna · 2019-03-12T09:18:19Z

src/node_perf.cc

+  if (*TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED(
+          TRACING_CATEGORY_NODE2(perf, reqwrap)) != 0) {
+    auto value = tracing::TracedValue::Create();
+    DumpToTracedValue(value.get());


I feel that it is an overkill to trace the whole Histogram on every call to Record.

We can tweak this later if necessary. How often would be acceptable?

Usually I would expect that traces act on raw data therefore trace type and delta on every call of Record.
I would not expect a trace holding the whole histogram in the same category as it is redundant information.

But as you said on summit the requirements what should be traced are missing in general so feel free to keep this as it is and adapt once there is a more clear picture in this.

We could tweak this a bit to be sensitive to detail level... e.g. output type and delta for category node.perf.reqwrap and the full histogram on node.perf.reqwrap.detail or something similar, but for now, I'd like to leave it as is.

Flarna · 2019-03-12T09:43:21Z

@jasnell Thanks! I like this solution.

The only drawback I see in adding filters is that the names of the async providers get to the public API surface even they are more an implementation detail. This is also the case in async_hooks and caused some discussions there in the past.
Not sure if this is a problem or can be handled in a proper way in docs.

jasnell · 2019-03-12T18:49:27Z

The only other way I could think of doing this would be to group by types of activity e.g. monitorRequestWrapLatency({ fs: true, net: true }) but we would have to be able to reasonably group the various types. There's some existing overlap there so I'm not sure if it's feasible. The only reason I went with the current approach is because we already make those names public in the async_hooks API.

jasnell · 2019-03-12T22:35:59Z

CI: https://ci.nodejs.org/job/node-test-pull-request/21483/

jasnell · 2019-03-12T23:29:31Z

~~New CI: https://ci.nodejs.org/job/node-test-pull-request/21484/~~
~~New New CI: https://ci.nodejs.org/job/node-test-pull-request/21488/~~
https://ci.nodejs.org/job/node-test-pull-request/21490/

Adds a histogram that tracks ReqWrap latency (defined as the length of time it takes from when the reqwrap is dispatched to when the callback is invoked)

jasnell · 2019-03-13T01:51:31Z

CI is good.

jasnell · 2019-03-13T16:00:02Z

@Flarna @addaleax @BridgeAR ... can I ask you to take another look... should be ready to go

Flarna · 2019-03-19T21:03:18Z

src/histogram-inl.h

+inline void Histogram::GetMin(
+    Histogram* histogram,
+    const FunctionCallbackInfo<Value>& args) {
+  double value = static_cast<double>(histogram->Min());


Min() returns int_max which results in min: 9223372036854776000 if no measurement was done (e.g. after reset()) which looks not that nice. Maybe set min/max to NAN in case count is 0?

BridgeAR · 2019-04-04T13:24:25Z

This needs a rebase.

jasnell · 2019-04-04T20:52:58Z

Yep, I'll be getting back to this next week.

jasnell · 2019-10-16T18:02:36Z

Sigh... looks like it took longer than a week to get back to this ;-) ... will be updating it soon

fhinkel · 2019-11-03T23:19:20Z

Should this remain open?

jasnell · 2019-11-04T00:17:47Z

Yes, please keep it open

…

On Sun, Nov 3, 2019, 15:19 F. Hinkelmann ***@***.***> wrote: Should this remain open? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#26556?email_source=notifications&email_token=AADLM6NGVZNPNSJGT2OZ6WLQR5E7DA5CNFSM4G44AP52YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEC57SZY#issuecomment-549189991>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AADLM6LSPBKSKRL5RJFG3FDQR5E7DANCNFSM4G44AP5Q> .

BridgeAR · 2019-12-20T01:08:51Z

Ping @jasnell

Qard · 2019-12-22T20:08:46Z

Took a quick pass at rebasing this but it seems to conflict with #29317, which makes ELDHistogram a HandleWrap now. I'm not sure how to resolve that without undoing that change as HistogramBase and RWLHistogram don't have the timer and therefore don't make sense as HandleWraps. However, HistogramBase extends from BaseObject, which means the ELDHistogram subclass couldn't independently extend from HandleWrap without introducing a diamond-of-death problem. 🤔

jasnell · 2019-12-22T20:53:47Z

I'll be picking this back up in the next couple of weeks.

jasnell · 2020-02-03T17:30:19Z

Going to go ahead and close this. I want to return to this but do not have time at present

jasnell added the semver-minor PRs that contain new features and should be released in the next minor version. label Mar 10, 2019

nodejs-github-bot added c++ Issues and PRs that require attention from people who are familiar with C++. lib / src Issues and PRs related to general changes in the lib or src directory. labels Mar 10, 2019

jasnell added the perf_hooks Issues and PRs related to the implementation of the Performance Timing API. label Mar 10, 2019

mcollina approved these changes Mar 10, 2019

View reviewed changes

bnoordhuis reviewed Mar 10, 2019

View reviewed changes

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

src/node_perf.cc Outdated Show resolved Hide resolved

BridgeAR reviewed Mar 10, 2019

View reviewed changes

doc/api/tracing.md Show resolved Hide resolved

vsemozhetbyt reviewed Mar 10, 2019

View reviewed changes

doc/api/tracing.md Show resolved Hide resolved

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

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

doc/api/perf_hooks.md Show resolved Hide resolved

vsemozhetbyt added performance Issues and PRs related to the performance of Node.js. trace_events Issues and PRs related to V8, Node.js core, and userspace code trace events. labels Mar 10, 2019

addaleax reviewed Mar 10, 2019

View reviewed changes

src/node_perf.cc Outdated Show resolved Hide resolved

jasnell force-pushed the req_wrap_latency branch from 861145a to d51cdb3 Compare March 11, 2019 01:45

Flarna reviewed Mar 11, 2019

View reviewed changes

lib/perf_hooks.js Outdated Show resolved Hide resolved

Flarna reviewed Mar 11, 2019

View reviewed changes

doc/api/perf_hooks.md Show resolved Hide resolved

vsemozhetbyt reviewed Mar 11, 2019

View reviewed changes

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

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

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

vsemozhetbyt reviewed Mar 12, 2019

View reviewed changes

doc/api/perf_hooks.md Show resolved Hide resolved

Flarna reviewed Mar 12, 2019

View reviewed changes

src/node_perf.h Outdated Show resolved Hide resolved

Flarna reviewed Mar 12, 2019

View reviewed changes

src/node_perf.cc Outdated Show resolved Hide resolved

Flarna reviewed Mar 12, 2019

View reviewed changes

perf_hooks: add reqwrap latency monitor

f4d1802

Adds a histogram that tracks ReqWrap latency (defined as the length of time it takes from when the reqwrap is dispatched to when the callback is invoked)

jasnell force-pushed the req_wrap_latency branch from cf7937a to f4d1802 Compare March 13, 2019 00:15

jasnell added the author ready PRs that have at least one approval, no pending requests for changes, and a CI started. label Mar 13, 2019

Flarna approved these changes Mar 13, 2019

View reviewed changes

Flarna mentioned this pull request Mar 15, 2019

perf_hooks: reset prev_ before starting ELD timer #26693

Closed

4 tasks

Flarna reviewed Mar 19, 2019

View reviewed changes

BridgeAR removed the author ready PRs that have at least one approval, no pending requests for changes, and a CI started. label Apr 4, 2019

Trott force-pushed the master branch from 1ecc406 to 49cf67e Compare September 17, 2019 16:51

devnexen force-pushed the master branch from e8a4568 to 5289f80 Compare December 26, 2019 19:46

jasnell closed this Feb 3, 2020

Flarna mentioned this pull request Mar 5, 2020

perf_hooks: precise mode for monitorEventLoopDelay #32102

Closed

4 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

perf_hooks: add ReqWrap latency monitoring #26556

perf_hooks: add ReqWrap latency monitoring #26556

jasnell commented Mar 10, 2019

nodejs-github-bot commented Mar 10, 2019

mcollina left a comment

BridgeAR commented Mar 10, 2019

jasnell commented Mar 10, 2019

vsemozhetbyt commented Mar 10, 2019

jasnell commented Mar 10, 2019

Flarna commented Mar 11, 2019

jasnell commented Mar 11, 2019

jasnell commented Mar 11, 2019

jasnell commented Mar 12, 2019

Flarna Mar 12, 2019

jasnell Mar 12, 2019

Flarna Mar 12, 2019

jasnell Mar 12, 2019

Flarna commented Mar 12, 2019

jasnell commented Mar 12, 2019

jasnell commented Mar 12, 2019

jasnell commented Mar 12, 2019 •

edited

Loading

jasnell commented Mar 13, 2019

jasnell commented Mar 13, 2019

Flarna Mar 19, 2019

BridgeAR commented Apr 4, 2019

jasnell commented Apr 4, 2019

jasnell commented Oct 16, 2019

fhinkel commented Nov 3, 2019

jasnell commented Nov 4, 2019 via email

BridgeAR commented Dec 20, 2019

Qard commented Dec 22, 2019

jasnell commented Dec 22, 2019

jasnell commented Feb 3, 2020

perf_hooks: add ReqWrap latency monitoring #26556

perf_hooks: add ReqWrap latency monitoring #26556

Conversation

jasnell commented Mar 10, 2019

Checklist

nodejs-github-bot commented Mar 10, 2019

mcollina left a comment

Choose a reason for hiding this comment

BridgeAR commented Mar 10, 2019

jasnell commented Mar 10, 2019

vsemozhetbyt commented Mar 10, 2019

jasnell commented Mar 10, 2019

Flarna commented Mar 11, 2019

jasnell commented Mar 11, 2019

jasnell commented Mar 11, 2019

jasnell commented Mar 12, 2019

Flarna Mar 12, 2019

Choose a reason for hiding this comment

jasnell Mar 12, 2019

Choose a reason for hiding this comment

Flarna Mar 12, 2019

Choose a reason for hiding this comment

jasnell Mar 12, 2019

Choose a reason for hiding this comment

Flarna commented Mar 12, 2019

jasnell commented Mar 12, 2019

jasnell commented Mar 12, 2019

jasnell commented Mar 12, 2019 • edited Loading

jasnell commented Mar 13, 2019

jasnell commented Mar 13, 2019

Flarna Mar 19, 2019

Choose a reason for hiding this comment

BridgeAR commented Apr 4, 2019

jasnell commented Apr 4, 2019

jasnell commented Oct 16, 2019

fhinkel commented Nov 3, 2019

jasnell commented Nov 4, 2019 via email

BridgeAR commented Dec 20, 2019

Qard commented Dec 22, 2019

jasnell commented Dec 22, 2019

jasnell commented Feb 3, 2020

jasnell commented Mar 12, 2019 •

edited

Loading