Max CPU Time Per Tick measurements are misleading

[enicholson]

Description

TLDR: I suspect using uv_getrusage to calculate tick times is including times from all Node.js threads and not wall clock time. This could be much higher on multicore systems.

We upgraded a Node.js application that we've been monitoring with New Relic for ages earlier this year from Node.js 8.x to 10.x (10.20.1 currently to be specific) and noticed at the time that most of the metrics looked much better. One that stood out was the Max CPU Time per tick which got noticeably worse. Unfortunately I don't have a great comparison right now, but we've seen maybe 50%-100% higher tick times. Unexpectedly total event loop ticks per minute is similar or higher.

We've recently been diagnosing some performance issues and max time per tick has been my go-to measurement for spotting responsiveness issues and our high tick times weren't manifesting in GC pressure, transaction latency, etc.

Digging into the code a little bit, I found LoopChecker::_checkCB is using uv_getrusage which is really just a wrapper around Unix getrusage. I found this snippet on Wikipedia:
POSIX functions clock() and getrusage() can be used to get CPU time consumed by any process in a POSIX environment. If the process is multithreaded, the CPU time is the sum for all threads. With Linux starting from kernel 2.6.26 there is a parameter RUSAGE_THREAD which leads to resource usage statistics for the calling thread only.

Expected Behavior

Event loop metrics would report wall-clock/single-threaded time that's more relevant to a Node.js developer.

Your Environment

• Node.js 10.20.1
• AWS Linux
• AWS c5.Xlarge ( 4 thread/2 core) VM

[michaelgoin]

Hi @enicholson,

Thank you for bringing this to our attention. I'm not familiar with the decisions around the original implementation but that does seem less than ideal as described. Digging into this further will get prioritized along with our other customer needs, so I can't guarantee a timeline.

That being said, we also welcome PR's if you (or anyone viewing this issue) want to propose a more ideal solution in a potential shorter timeline.

Thanks,

Michael

[enicholson]

Here's a little more relevant info/doc. Node.js Process.getResourceUsage mentions it uses uv_getrusage and that the time values are the same as Process.cpuUsage. That specifies more clearly:
These values measure time spent in user and system code respectively, and may end up being greater than actual elapsed time if multiple CPU cores are performing work for this process.

I think that explains why the LoopChecker seems accurate when running locally but has inflated values when our real service is under load. If Node.js 10 is more effectively multithreading (IO, encryption, background GC etc) than Node.js 8.x that would explain why the "max time per tick" is higher even though other measures of responsiveness have improved.

[enicholson]

Thanks Michael, We'll work with our account team. Meaningful event loop timing would be really useful right now.

Cheers!

[workato-integration]

https://new-relic.atlassian.net/browse/NR-292138

[kmudduluru]

We are exploring options on Node runtime metrics , instead of native-metrics due to these challenges. Create spike ticket in the backlog