monitorEventLoopDelay metrics are completely off especially the count

[rochdev]

Version

v23.3.0

Platform

Darwin Rochs-MBP-3710.localdomain 23.4.0 Darwin Kernel Version 23.4.0: Wed Feb 21 21:44:43 PST 2024; root:xnu-10063.101.15~2/RELEASE_ARM64_T6000 arm64

Subsystem

perf_hooks

What steps will reproduce the bug?

const { monitorEventLoopDelay } = require('perf_hooks')
const h = monitorEventLoopDelay({ resolution: 1 })

h.enable()

setInterval(() => {
  // Just to trigger an event loop iteration 10x per second.
}, 100)

setTimeout(() => {
  console.log(h)
}, 1000)

How often does it reproduce? Is there a required condition?

Every time.

What is the expected behavior? Why is that the expected behavior?

The expected behaviour would be to get accurate metrics about event loop delay without impacting the event loop itself. In the above example, I would expect to see ~10 iterations.

What do you see instead?

Using monitorEventLoopDelay alters the behaviour of the event loop, causing it to run more than necessary and preventing it from idling. This means that after 1 second with a resolution of 1, you get ~1000 iterations in 1 second for an app that is mostly idle because of the added timer.

Another similar issue is that even the metrics themselves are wildly inaccurate as described in #34661

Additional information

It seems to me that this is a fundamental issue with the approach that was used to capture these metrics, and the function would need to be rewritten in order to provide accurate information.

One way to do this that we've been using successfully for years at this point is to collect timing information with 2 hooks on libuv around the non-IO part of the loop to isolate user code. While it's not 100% accurate, it's definitely way more accurate than the current approach and doesn't skew regardless of very low (0-10) or very high (thousands to millions) iterations. Here is a code snippet of the alternative approach: https://github.com/DataDog/dd-native-metrics-js/blob/4b326d5a1669e7a69c5c84a4d3e036163e60b9d5/src/metrics/EventLoop.hpp#L72-L96

I'm willing to open a PR to fix the issue by reworking the internals to monitor libuv directly instead of relying on a timer, but I first wanted to open this issue to see what others think, and if there may be better approaches or subtle potential issue with the proposed new approach. If it sounds good to everyone then I'll just go ahead with a PR. We've been waiting for a long time to get this out of the box, and thought that we could finally remove our native addon but this ended up not being the case, so I'm pretty motivated to help any way I can to fix this.

[rochdev]

Thinking about this more, I think this could actually be separated as 2 issues:

1. The event metrics are inaccurate because they are being captured from a timer instead of directly from the event loop. This could be addressed by using libuv hooks instead.
2. The IntervalHistogram class causes additional iterations of the event loop because it adds a timer. This is wasteful because realistically the histogram only needs to be updated if the application is accessing it which means it's not idling. When the application is idling there is no need to update the histogram. It seems then that the histogram could also be updated using libuv hooks instead of a timer, and compare the time of the previous iteration to know if it should update based on the resolution.

Since both problems are addressed by adding libuv hooks, I think they could be solved in a single PR which would also preserve the API of monitorEventLoopDelay since it would still be possible to accept a resolution parameter and use a revamped IterationHistogram that doesn't force additional iterations.

[constantind]

The same in 20.x. It should rather use observable pattern for the state of libuv reporting back rather than load it more to measure it. Also has memory leak Node/Detached IntervalHistogram from the base histogram.reset here: https://github.com/siimon/prom-client/blob/master/lib/metrics/eventLoopLag.js#L63
possibly caused by this in 20.x #51296