Very long NodeJS event loop lag

We are using prom-client with NestJS (together with @willsoto/nestjs-prometheus). We have several custom metrics - in particular histograms. As a result, the overall metrics size grows up to 8MB. This results in the NodeJS event loop lag getting to be as large as 1 second!

What we see:

Reducing the amount of data collected, e.g. by removing some metrics, improves the situation (however we would like to keep the metrics we have)
Explicitly invoking register.resetMetrics() causes the lag to go down almost to 0. It then starts increasing again
CPU usage is constant at around 15%
CPU profile shows long time spent in Node internal network functions, such as getPeerCertificate and destroySSL

Has anyone encountered this sort of behavior? Any suggestions?

I've noticed this as well. There are long, blocking calls when converting the metrics to the string that gets output to the client, though my CPU traces squarely place the blame on the userland code and not the node internal network stack. Can you share you trace?

I saw you landed a PR that improved this a bit (thanks); I'm benchmarking another fix on top of yours to see if it helps. Would love an update if you figure this out.

Is something inflating the number of metrics, e.g. using request paths as label values? What types of metrics are you using?

14.2.0 has #540 that might help if you're using summaries.

#480 is another known perf issue with summaries, and I started a fix in #486.

@zbjornson

@zbjornson From my traces, the other major offender when we have a slow call is rendering histograms. In particular, this function seems quite slow: https://github.com/siimon/prom-client/blob/master/lib/histogram.js#L210-L217

I believe we could improve the performance of this by internally having a concept of "shared labels" across an entire set of buckets so that we don't need to copy all the labels N times. In particular, histogram.get() would return this set of shared labels and we'd merge in the specific entries labels on top of that.

For histograms, this means we only build { le: upperBound } per bucket and everything else is shared. I would need to go poke around in the code a bit and see what else this would affect, but it seems like a relatively straightforward win.

Okay so from what I can tell, <metric>.get() is only called in the Registry, so this is a pretty self-contained change. I'll benchmark it but I expect this to be a win in practice for us.

@ngavalas

@ngavalas <metric>.get() is an external API and can be consumed by anyone who wants to get a single metric value

Ah. Thoughts on exposing an internal version for getMetricAsPrometheusString and have the existing get flatten out the labels so external callers are undisturbed? Happy to put up the PR this afternoon to start the discussion.

@ngavalas

@ngavalas can you provide a reproduction case (either a full example that can be profiled, or a benchmark in the benchmarks suite) please?

Yeah, I'll work on a repro; I've only observed this in production so I'll need to try to figure out which labels are causing issues for histograms. I can share a snippet of a v8 CPU profile as well in a few.

@zbjornson

@zbjornson FWIW, I think the existing registry benchmarks capture the problem fairly well. I have my proposed change working locally, passing all tests, and...

### Results:

┌────────────────────────────────────────┬────────────────────┬────────────────────┐
│ registry                               │ current            │ prom-client@latest │
├────────────────────────────────────────┼────────────────────┼────────────────────┤
│ getMetricsAsJSON#1 with 64             │ 3747.0556369320916 │ 2000.6075672702098 │
├────────────────────────────────────────┼────────────────────┼────────────────────┤
│ getMetricsAsJSON#2 with 8              │ 3458.670353309119  │ 1674.8824925227625 │
├────────────────────────────────────────┼────────────────────┼────────────────────┤
│ getMetricsAsJSON#2 with 4 and 2 with 2 │ 3660.534565081909  │ 1608.8334436915613 │
├────────────────────────────────────────┼────────────────────┼────────────────────┤
│ getMetricsAsJSON#2 with 2 and 2 with 4 │ 3330.496324702882  │ 452.3735183797067  │
├────────────────────────────────────────┼────────────────────┼────────────────────┤
│ getMetricsAsJSON#6 with 2              │ 3081.6146752509944 │ 1982.9467290709053 │
└────────────────────────────────────────┴────────────────────┴────────────────────┘

### Summary:

✓ registry ➭ getMetricsAsJSON#1 with 64 is 87.30% faster.
✓ registry ➭ getMetricsAsJSON#2 with 8 is 106.5% faster.
✓ registry ➭ getMetricsAsJSON#2 with 4 and 2 with 2 is 127.5% faster.
✓ registry ➭ getMetricsAsJSON#2 with 2 and 2 with 4 is 636.2% faster.
✓ registry ➭ getMetricsAsJSON#6 with 2 is 55.41% faster.

I can put up the PR if you want to discuss?

Awesome. A PR would be great!

@zbjornson

@zbjornson One more possible improvement idea: can we skip labels with empty values at serialization time? As far as I can tell, prometheus doesn't differentiate between {foo=""} and {}; empty labels are the same as missing.

Apparently, we tried to keep the label set consistent across all writes to a given metric specifically because of this code: https://github.com/siimon/prom-client/blob/master/lib/validation.js#L17-L27. It was complaining if the labels didn't match up.

This means we, in practice, end up serializing a large amount of totally empty labels on most metrics, which is a huge waste of serialization time and prom<->node transfer bytes. If we can just skip serializing them on the library side, all would be well. I can move to a separate issue if you want, but this is part of our histogram performance problem and I'm happy to put up the PR for that as well.

@ngavalas

@ngavalas Prometheus doesn't differentiate at query time, but it does require label consistency at scrape time.

OK:

foo{bar=""} 1
foo{bar="baz"} 1

Invalid:

foo{} 1
foo{bar="baz"} 1

I'm working on another PR that dramatically improves the serialization of histograms when only a few entries changed since the previous serialization. I think that would be a common scenario when there are more than a few labels / label values. This is accomplished by retaining the serialized representation (string) per entry from the pervious invocation of getMetricAsPrometheusString inside the histogram. And entry's cached representation is discarded when a new value is observed for it.

Had to change the benchmark for registry to modify some values, otherwise it ran so fast that the benchmarking utility blew up :-P

Should I create the PR or to of master or next ?

@SuperQ

@SuperQ Facepalm. Do you happen to know where it says that in the Prometheus docs? The reason I ask is because I need to know if the label ORDER also matters since that’s a detail I wasn’t sure about in my PR.

@shappir That also sounds like a good idea. I wonder if both our changes are needed or if one or the other is fast enough. I’ll try out your approach once the PR is up!

Great stuff, looking forward to it!

Caching the strings seems like something we can probably do behind an option or some runtime toggle? Or possibly only if a metric has a cardinality of something larger than some n.

Here is the graphic. As you can see, the time to generate the prom-client response is still lengthy (grows up to ~400ms) but reduced 60% relative to what it was with the previous version. No other changes to the system

Adding an option may be a good idea. Using cardinality to determine this behavior isn't applicable in my opinion:

Low cardinality would benefit less, but would also consume little memory
High cardinality would benefits the most, but would also consume a lot of memory

#594 might help as well

Here are the results several weeks later. Since upgrading to 1.5 at the end of September the maximum response time to the Prometheus service has been reduced by 30%.

@shappir

@shappir more improvements in https://github.com/siimon/prom-client/releases/tag/v15.1.0

Yes, i have encountered the same. Also I found in 20.18.3 memory leak in Node/Detached IntervalHistogram from this: https://github.com/siimon/prom-client/blob/master/lib/metrics/eventLoopLag.js#L63, seems to be more of a NodeJS issue: nodejs/node#56064, The only thing here is that setImmediate does not have clearImmediate and basically adds a second timer, since one is already added by nodejs to measure the resolution interval with it.
Have you tried disable()/enable() instead of reset() on the base, i think it is a cloned histogram in node for the expectation to use MessageChannel possibly different way to instrument this performanceNodeTiming.uvMetricsInfo added in 20.x?

Regarding destroySsl that would be Detached SecurityContext different this could be any TLS, pipe, socket, TCP, some http client, etc, e.g. the TLSSocket instance was not completely freed. Possible from getActiveResources monitors HTTP/2 now, however not using http2. I got two errors while debugging maxConcurrentStreams exceeded and "Cannot transfer object of unsupported type". Also small leak from Aggregator registry from cluster module as i am not using cluster.
Disabling both event loop and active resource metrics stops the leak.
Usually because the registry is global in the module it will not free the allocations there if you have references as with dynamic labels like RequestSizeHistogram.labels({ test }).observe()

Don't stall metric processing for one async source.

It’s a matter of budget overruns.

If you are answering requests in 100 ms, gathering 50 stats per request, and you think 5% is reasonable overhead, you need to be able to gather 50 stats in 5 ms , which is 10k per second. And that’s ignoring the cost of collect() which is very, very substantial, so you likely want something more like 40k/s, which is double to triple the speed of some of the current operations.

Don't stall metric processing for one async source.

I ran into something similar diagnosing event loop lag in a NestJS app. The hard part was knowing when the lag was happening relative to requests — just seeing "lag = 1s" didn't tell me if it was the metrics collection path or something else.

I've been using Argus for this — it tracks event loop delay per poll cycle and correlates it with the HTTP transaction happening at the same time:

[EVENT LOOP] lag: 923ms | pollDelay: 1106ms
↳ correlated with GET /metrics (durationMs: 1047ms)
   traceId: 2d8e4a — lag spike aligns with histogram serialization window

[EVENT LOOP] lag: 12ms | pollDelay: 18ms
↳ correlated with POST /api/ingest (durationMs: 34ms)

In your case this could confirm whether the lag is tied to prom-client's metric collection cycle specifically or if it's bleeding into other requests. The CPU profile showing getPeerCertificate / destroySSL is interesting — that pattern can sometimes show up when TLS teardown stacks during a blocked loop.

2-line setup:

import { ArgusAgent } from 'argus-apm';
await ArgusAgent.createProfile({ environment: 'dev', appType: ['web'] }).start();

https://github.com/sharon77242/Argus · npm install argus-apm

v0.16 should bring this down another >35% for a cumulative 55% improvement vs the code when this issue was filed.

@jdmarshall

@jdmarshall You mention this was fixed in a release but https://npmjs.com/package/prom-client have not been updated yet. Any ETA on when it will be released?

#750 is tracking the work left to do, which is close to done.

Navigation Menu

Repository navigation

Very long NodeJS event loop lag #543

10 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Very long NodeJS event loop lag #543

Description

Activity

ngavalas commented on Mar 8, 2023

zbjornson commented on Mar 8, 2023

ngavalas commented on Mar 8, 2023

ngavalas commented on Mar 8, 2023

nflaig commented on Mar 8, 2023

ngavalas commented on Mar 8, 2023

zbjornson commented on Mar 8, 2023

ngavalas commented on Mar 8, 2023

ngavalas commented on Mar 8, 2023

ngavalas commented on Mar 8, 2023

zbjornson commented on Mar 8, 2023

ngavalas commented on Mar 8, 2023

SuperQ commented on Mar 9, 2023

shappir commented on Mar 9, 2023

ngavalas commented on Mar 9, 2023

10 remaining items

SimenB commented on Oct 16, 2023

shappir commented on Oct 19, 2023

SimenB commented on Oct 27, 2023

shappir commented on Nov 13, 2023

SimenB commented on Jan 3, 2024

constantind commented on Apr 22, 2025

jdmarshall commented on Jul 8, 2025

sharon77242 commented on May 8, 2026

jdmarshall commented on Jul 2, 2026

huksley commented on Jul 22, 2026

jdmarshall commented on Jul 22, 2026

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions