newrelic / newrelic/node-native-metrics

Max CPU Time Per Tick measurements are misleading

Open
#116 5 comments 2 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

feature-request
Dominant language
C++
Stars
62
Forks
40
PR merge metrics
No merged PRs in 30d

Description

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

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start with LoopChecker::_checkCB and trace how uv_getrusage contributes to the tick-time metric. Compare the reported CPU time with the expected wall-clock or event-loop-thread measurement on the described multithreaded environment; done means the event loop metrics reflect the timing relevant to Node.js responsiveness.

Written by the indexing model from the issue text.

Assessment

Tech stack
node.js
Domain
observability-sre, performance
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
38/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.