Very long NodeJS event loop lag

[shappir]

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?

[ngavalas]

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.

[zbjornson]

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.

[ngavalas]

@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.

[ngavalas]

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.

[nflaig]

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

[ngavalas]

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.

[zbjornson]

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

[ngavalas]

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.

[ngavalas]

@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.

[ngavalas]

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

[zbjornson]

Awesome. A PR would be great!

[ngavalas]

@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.