2.3.0 significatnt memory usage increase.

[tcolgate]

Bug Report

What did you do?
Upgraded to 2.3.0

What did you expect to see?
General improvements.

What did you see instead? Under which circumstances?
Memory usage, possibly driven by queries, has considerably increased. Upgrade at 09:27, the memory usage drops on the graph after then are from container restarts due to OOM.

container_memory_usage_bytes

Environment

Prometheus in kubernetes 1.9

• System information:
  Standard docker containers, on docker kubelet on linux.

• Prometheus version:
  2.3.0
  insert output of prometheus --version here

[brian-brazil]

Can you share your configuration, a snapshot of the benchmark dashboard, and if you've made any other changes?

[tcolgate]

@brian-brazil where do I find the "benchmark dashboard", and the config for this is rather large are there any specific areas of interest?

[tcolgate]

Found the dashboard
https://snapshot.raintank.io/dashboard/snapshot/wo7UNJeCrtIGGt6Wgf3Xxgkvvf63QBTK

[brian-brazil]

The entire config please, we don't know what might be relevant.

[tcolgate]

Obfuscated by hand, hopefully didn't introduce any additional problems.
We also have a large'ish number of recording rules, due to the heritage of the tooling, these are all in individual rules groups, 1 per group. Not sure if that will have any bearing on things.
config.yaml.txt

[brian-brazil]

Summary of config: 15s interval, using 13 gce_sd_configs and I think 36 kuberentes_sd_configs.

[brian-brazil]

How often is the config file being reloaded? Can you try running it without the rules to eliminate those?

[tcolgate]

sounds about right.
We have a sidecar that discovers kube clusters within a gce project, we run a prom per project (this config also has some additional scrapes for non-kubernetes GKE instances. This is one of the larger instances but has been running fine on 2.2.1.
The kube scrapes can probably be simplified at this point to just the pod discovery, but I don't think the number of scrapes is the problems.

[tcolgate]

config reload only occurs on recording rule publishing, (in the order of < 1 / day).
Unfortunately it will be a while before I can spin up another 2.3 just to test.

Here's a before/after (the blue annotation shows when I reverted to 2.2.1)
https://snapshot.raintank.io/dashboard/snapshot/p9PmKT5K5D57RicIZOZQzdrAsez7vOF8

FWIW queries should be relatively consistant across the timespan of that plot.

[brian-brazil]

My primary suspicions would be on kuberentes_sd, as that changed a good bit. Query memory should only have gone down - which your graphs show.

[tcolgate]

My original graph may be incredibly misleading. I thought the spikes were the cause of the OOM, now I realise that is show the total allocated CPU so the spikes are actually two instances running, not one, I think the instance is already over its mrmory budget.

[fabxc]

@tcolgate could you provide a heap profile SVG when the usage is very high?

go tool pprof -symbolize=remote http://<prometheus>/debug/pprof/heap

And then svg > heap_inuse.svg.

[tcolgate]

@fabxc I've up'd the memory request to 26GB, which I think is enough now that at least it doesn't get OOM'd (it's pretty much on a dedicated node now).
During the high memory usage spikes, I see scrap interval percentiles climb and sample ingestion drop significantly.
I got the attached capture during one of these spikes (or at least on the way to one)
heap_inuse_break.svg.gz

[tcolgate]

internal prom perf dashboard capture during that profile: https://snapshot.raintank.io/dashboard/snapshot/si3JoG47UshfAlbwdLg6GgCiXvFep4JQ
benchmark dashboard:
https://snapshot.raintank.io/dashboard/snapshot/tHqUYJjmoeAamZ5GtHTBrEFbL4Zu6tTS

[fabxc]

Thanks for the quick response. That appears to be a 30s CPU profile, which looks fairly normal.
Are you sure you used a URL ending in /heap and not /profile?

[tcolgate]

Doh
@fabxc I think I got this just as the scrape latency was increasing:
heap_inuse_break.svg.gz

[fabxc]

This profile does not show any service discovery at all, i.e. usage is probably very minor. The graph your first posted also indicates that usage didn't increase continuously but rather spikes a lot. The baseline seems to be a bit lower than before actually.

Can you get another profile with the -alloc_space flag added? Would be good if the server has been seeing those spikes already for a while.

[tcolgate]

This is a alloc_space one from during the climbing memory
allocs3.svg.gz

This one seems to suggest that the labels built up during scraping are the problem? What's changed around the scrapes? more concurrency maybe?

[brian-brazil]

Do you have a normal heap_inuse and one during a spike?

[tcolgate]

@brian-brazil I think the previous one was at the start of one. Timing is tricky as things become unresponsive. I've had to revert now as I've tested these on a prod instance (thanks to the kind patience of some devs).

[fabxc]

The allocs profile only shows allocations, recording rule evaluations, and serving Prometheus's own /metrics endpoint. The rest is below the threshold for being displayed.

My best guess for now is thus PromQL. The CPU profile doesn't show much GC work, which indicates that generally the allocation improvements in 2.3 are working. But possibly the changed evaluation model pins to much memory for a single query at once? – I've no hard reasoning for this though.

@tcolgate any chance you can share (possibly privately) the recording rules that server is running so we can get an understanding of the queries that are running?

[brian-brazil]

Could you also spin up a test server without the recording rules?

[tcolgate]

@brian-brazil that's going to take me a while. I can try and find the time tomorrow

[brian-brazil]

But possibly the changed evaluation model pins to much memory for a single query at once? – I've no hard reasoning for this though.

I can only imaging that happening with very high churn in the underlying data, which the graphs don't show.

[krasi-georgiev]

@tcolgate did you do any other changes apart from just upgrading the prom version?

[tcolgate]

@krasi-georgiev nope, just upgraded. I've updated and reverted a few times, behaviour is consistant. 2.3.0 crashes, 2.2.1, stable.

[rajatjindal]

@tcolgate , the graphs that you shared are very interesting. we are also using Prometheus and running into performance issues when we enabling remote storage. (it might be a completely different issue)

is there a place where we can import these dashboards from? will be interesting to see these metrics

[tcolgate]

@rajatjindal The Prometheus Benchmark dashboard is available on grafana.net (make sure you get the 2.0 version), and the other dashboard is our internal prom dashboard, better dashboards exist on grafana.net (our is adapted from one of the earlier v1 prometheus perf dashboards)

[free]

From the -alloc_space profile, it looks to me like more than half the memory allocations during scraping (16 of 29 GB, in scrape.mutateSampleLabels) and about a quarter of those during rule evaluation (14 of 55 GB, 10 GB in promql.dropMetricName and 4 GB in promql.(*evaluator).aggregation) are labels.Builder instances.

#4248 tries to optimize away the latter 4 GB (and I've seen it use 10x less memory for query_rangerequests for aggregated rate queries -- sum by(foo) (rate(bar[5m]))), but if that turns out not to be the main cause, I can think of a couple of ways of getting rid of the other, larger, allocations:

• For scrape.mutateSampleLabels, barring any race conditions, reuse the labels in scrape.scrapeCache.seriesPrev where available, instead of creating new ones on each scrape.
• For promql.dropMetricName, turn labels.Labels into an interface, with a base implementation (the current one) plus a wrapper around it, that dynamically filters away some labels.

Neither is a particularly difficult technical challenge and might be worth pursuing even if the root cause turns out to be totally different (which I actually doubt).

[free]

Oh, and on a related note, while testing my humongous aggregated rate query_range requests, I'm seeing significantly more memory usage the first time I run said requests after long pauses (hours or days) than on subsequent runs. I.e. starting from a steady state go_memstats_heap_inuse_bytes of about 500 MB, the first spike goes to 2.3 GB, subsequent ones to only 1.1 GB.

I haven't managed to pinpoint the cause, but I imagine it's the TSDB loading everything.

[tcolgate]

I've managed to trigger it again, got a allocs svg, but I don't think that is terriby useful (seems to be since the process started?)
heap_allocs.svg.gz

There seems to be some kind of time/event element to this, but it doesn't obviously align with some other event having occurred. Basically, if I leave the thing alone for an hour or so, I can trigger the OOM by using the federate query. At some time before this, I can hammer federate mercilessly without issues (tried hitting it with hey).

I need to head off soon. Tomorrow I'll try and capture a CPU profile during a crash.

[brian-brazil]

This is smelling like a TSDB issue and it doesn't align with blocks, so it's probably chunks.

[brian-brazil]

I've looked through the code changes on the federation codepath between 2.3.0 and 2.2.1, there's a few changes on the path but none of them seem plausible.

[tcolgate]

I've not been able to trigger a crash this morning as yet. I'll give it a try every 10 mins or so and see if I can get a trace during the crash, 🤞

[brian-brazil]

I'm currently suspecting it's #4185. If you can reproduce again, try rolling that one back.

[brian-brazil]

Also if you could try the federate call without the {job="prometheus"}, to see if it's overlapping selectors that's the issue.

[tcolgate]

removing the {job="prometheus"} doesn't seem to trigger the problem any more reliably. Not managed to crash it yet today.

[brian-brazil]

I would expect removing the {job="prometheus"} to reduce the chances of a crash, as it's a simpler code path.

[tcolgate]

Any suggestions of how I can update the /federate to make it more likely to trigger your guess? I'd rather be able to reliably reproduce the problem.

[brian-brazil]

Adding some duplicate matchers might do it, but it's a bit of a shot in the dark.

[tcolgate]

I repeated one of the matchers a couple of times and boom, that did it. and I appear to be able to crash it on demand. Impressive in-the-dark shooting there!
out.trace.gz

[brian-brazil]

Okay, I can reproduce locally now on a Prometheus scraping only itself.

[brian-brazil]

Okay, the issue is if you try to federate a NaN value from a time series that more than one selector returns. NaN's never equal themselves, so it looks like a different value even though it's the same. So we end up in an infinite loop, which is also buffering up all these duplicate points in RAM.

[tcolgate]

@brian-brazil great catch, cheers. I'll try a build from release-2.3 once you've merged

[lock]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.