Repository navigation
Conversation
metricMap.Collect held the vector's read lock while sending its children to the Gather channel. The only consumer of that channel is the Gather goroutine, which also calls Metric.Write for every metric it receives. When one Write was slow or stuck, the channel filled up, Collect blocked on the send with the read lock held, the first WithLabelValues call with a new label set queued on the write lock and, because sync.RWMutex prefers waiting writers, every WithLabelValues call on the vector blocked from then on. Collect now snapshots the children under the read lock and sends them after releasing it. The cost is one temporary slice per Collect. A child deleted after the snapshot can still be sent once in that Collect, and Delete and Reset no longer wait for a slow consumer. Fixes prometheus#2147 Signed-off-by: lif0 <22912194+lif0@users.noreply.github.com>
|
fixed conflicts |
lif0
changed the title
lif0
changed the title
lif0
changed the title
| defer m.mtx.RUnlock() | ||
|
|
||
| kadi := 0 | ||
| for _, metrics := range m.metrics { |
There was a problem hiding this comment.
Wouldn't this buffer your 33k series (or I assume part of it from the large vector?) into memory, which on constantly blocked ch <- in your case would result in the memory leak?
There was a problem hiding this comment.
No, the snapshot does not copy the series. It is a []Metric, so 16 bytes per child. Each entry points to a metric that already lives in the vector map. The metric data itself is not copied.
I measured it on this branch. The largest vector from the issue has 2084 children and the snapshot takes 40 KiB. If every vector on the 33k target is blocked at the same time, the total is about 528 KiB per Gather. The slice is freed when Collect returns. If Write never returns, that Gather is already leaked with or without this change, and in our heap profile one stuck Gather held about 3.4 MB of partial response (3483 MB / 1032 stuck scrapes). The snapshot adds at most 15% to that.
I agree that #2162 fixes the root cause of this case. This change works together with it. Any slow or stuck Write even one from a custom Collector, no longer blocks WithLabelValues in the application.
There was a problem hiding this comment.
max latency of GetMetricWithLabelValues with a new label during a normal Gather, Write is never stuck. Details and test code in #2147
| case | before | after |
|---|---|---|
| 5000 children, real gauge Write | 2.5 ms | 30 µs |
| 2000 children, write takes about 1 ms per call | 1.14 s | 160 µs |
| 900 children, write takes about 1 ms per call | 50 µs | 160 µs |
There was a problem hiding this comment.
Cool. Can we add a quick microbenchmark to confirm memory assumptions for those gather cases? (and allow next developers to reuse when we change this code).
There was a problem hiding this comment.
Added BenchmarkGatherMetricVec in registry_test.go. Gauge is the worst case for this change, its Write is almost free, so the cost of the snapshot is easy to see. Histogram with the same sizes shows the change next to a realistic Write.
| after vs before | |
|---|---|
| allocations per Gather | +1 per vector in all cases |
| memory per Gather | +16 B per child, rounded up to the size class, so +160 B at 10, +16 KiB at 900, +32 KiB at 2000, +80 KiB at 5000 children. For gauge this is +5.5%, for histogram +0.9%, the extra bytes are the same, but the whole Gather is bigger |
| time, gauge, Apple M2, 8 cores | +2.9% at 10, within noise at 900, +9.7% at 2000, +10.7% at 5000 |
| time, gauge, Linux, 3 cores | +5.5% at 10, +8.2% at 900, +7.3% at 2000, +7.5% at 5000 |
| time, histogram, Apple M2, 8 cores | within noise at 10, 900 and 5000, +7.7% at 2000 |
| time, histogram, Linux, 3 cores | +5.3% at 10, +4.3% at 900, within noise at 2000 and 5000 |
Memory matches the assumption. The time cost is the Gather goroutine waiting for the snapshot before it gets the first metric, the old code started sending during the first map iteration. It is a few percent of Gather. The benefit is that WithLabelValues no longer waits for the scrape, see the latency table above.
It would be good if you could run it on your machine too:
go test -run xxx -bench BenchmarkGatherMetricVec -benchmem -count=6 ./prometheus/
macOS, Apple M2, 8 cores, darwin/arm64
│ before.txt │ after.txt │
│ sec/op │ sec/op vs base │
GatherMetricVec/gauge/children=10-8 8.565µ ± 4% 8.815µ ± 7% +2.92% (p=0.026 n=6)
GatherMetricVec/gauge/children=900-8 380.1µ ± 11% 394.7µ ± 3% ~ (p=0.065 n=6)
GatherMetricVec/gauge/children=2000-8 1.061m ± 1% 1.163m ± 1% +9.71% (p=0.002 n=6)
GatherMetricVec/gauge/children=5000-8 2.932m ± 8% 3.245m ± 6% +10.67% (p=0.002 n=6)
GatherMetricVec/histogram/children=10-8 13.31µ ± 4% 13.65µ ± 2% ~ (p=0.240 n=6)
GatherMetricVec/histogram/children=900-8 941.2µ ± 8% 984.4µ ± 6% ~ (p=0.132 n=6)
GatherMetricVec/histogram/children=2000-8 2.258m ± 3% 2.432m ± 3% +7.69% (p=0.002 n=6)
GatherMetricVec/histogram/children=5000-8 6.732m ± 14% 7.025m ± 2% ~ (p=0.065 n=6)
geomean 457.7µ 484.1µ +5.76%
│ before.txt │ after.txt │
│ B/op │ B/op vs base │
GatherMetricVec/gauge/children=10-8 35.20Ki ± 0% 35.35Ki ± 0% +0.44% (p=0.002 n=6)
GatherMetricVec/gauge/children=900-8 291.2Ki ± 0% 307.2Ki ± 0% +5.50% (p=0.002 n=6)
GatherMetricVec/gauge/children=2000-8 599.6Ki ± 0% 631.6Ki ± 0% +5.34% (p=0.002 n=6)
GatherMetricVec/gauge/children=5000-8 1.377Mi ± 0% 1.456Mi ± 0% +5.67% (p=0.002 n=6)
GatherMetricVec/histogram/children=10-8 49.80Ki ± 0% 49.96Ki ± 0% +0.31% (p=0.002 n=6)
GatherMetricVec/histogram/children=900-8 1.568Mi ± 0% 1.584Mi ± 0% +1.00% (p=0.002 n=6)
GatherMetricVec/histogram/children=2000-8 3.439Mi ± 0% 3.470Mi ± 0% +0.91% (p=0.002 n=6)
GatherMetricVec/histogram/children=5000-8 8.511Mi ± 0% 8.589Mi ± 0% +0.92% (p=0.002 n=6)
geomean 618.0Ki 633.3Ki +2.48%
│ before.txt │ after.txt │
│ allocs/op │ allocs/op vs base │
GatherMetricVec/gauge/children=10-8 65.00 ± 0% 66.00 ± 0% +1.54% (p=0.002 n=6)
GatherMetricVec/gauge/children=900-8 3.648k ± 0% 3.649k ± 0% +0.03% (p=0.002 n=6)
GatherMetricVec/gauge/children=2000-8 8.059k ± 0% 8.060k ± 0% +0.01% (p=0.002 n=6)
GatherMetricVec/gauge/children=5000-8 20.08k ± 0% 20.08k ± 0% +0.00% (p=0.002 n=6)
GatherMetricVec/histogram/children=10-8 305.0 ± 0% 306.0 ± 0% +0.33% (p=0.002 n=6)
GatherMetricVec/histogram/children=900-8 25.25k ± 0% 25.25k ± 0% +0.00% (p=0.002 n=6)
GatherMetricVec/histogram/children=2000-8 56.06k ± 0% 56.06k ± 0% ~ (p=0.061 n=6)
GatherMetricVec/histogram/children=5000-8 140.1k ± 0% 140.1k ± 0% +0.00% (p=0.032 n=6)
geomean 6.247k 6.262k +0.24%
Linux, 3 cores, linux/arm64, go1.26.0
│ before.txt │ after.txt │
│ sec/op │ sec/op vs base │
GatherMetricVec/gauge/children=10-3 10.66µ ± 6% 11.24µ ± 5% +5.51% (p=0.041 n=6)
GatherMetricVec/gauge/children=900-3 407.5µ ± 8% 440.7µ ± 3% +8.16% (p=0.015 n=6)
GatherMetricVec/gauge/children=2000-3 1.064m ± 5% 1.142m ± 3% +7.32% (p=0.004 n=6)
GatherMetricVec/gauge/children=5000-3 2.976m ± 2% 3.198m ± 4% +7.47% (p=0.002 n=6)
GatherMetricVec/histogram/children=10-3 17.29µ ± 2% 18.20µ ± 5% +5.26% (p=0.002 n=6)
GatherMetricVec/histogram/children=900-3 1.215m ± 2% 1.267m ± 10% +4.27% (p=0.004 n=6)
GatherMetricVec/histogram/children=2000-3 2.839m ± 2% 2.864m ± 8% ~ (p=0.485 n=6)
GatherMetricVec/histogram/children=5000-3 7.060m ± 6% 7.179m ± 5% ~ (p=0.310 n=6)
geomean 525.2µ 551.7µ +5.04%
│ before.txt │ after.txt │
│ B/op │ B/op vs base │
GatherMetricVec/gauge/children=10-3 35.20Ki ± 0% 35.35Ki ± 0% +0.44% (p=0.002 n=6)
GatherMetricVec/gauge/children=900-3 291.1Ki ± 0% 307.1Ki ± 0% +5.50% (p=0.002 n=6)
GatherMetricVec/gauge/children=2000-3 599.6Ki ± 0% 631.6Ki ± 0% +5.34% (p=0.002 n=6)
GatherMetricVec/gauge/children=5000-3 1.377Mi ± 0% 1.455Mi ± 0% +5.67% (p=0.002 n=6)
GatherMetricVec/histogram/children=10-3 49.80Ki ± 0% 49.96Ki ± 0% +0.31% (p=0.002 n=6)
GatherMetricVec/histogram/children=900-3 1.568Mi ± 0% 1.584Mi ± 0% +1.00% (p=0.002 n=6)
GatherMetricVec/histogram/children=2000-3 3.439Mi ± 0% 3.470Mi ± 0% +0.91% (p=0.002 n=6)
GatherMetricVec/histogram/children=5000-3 8.511Mi ± 0% 8.589Mi ± 0% +0.92% (p=0.002 n=6)
geomean 618.0Ki 633.3Ki +2.48%
│ before.txt │ after.txt │
│ allocs/op │ allocs/op vs base │
GatherMetricVec/gauge/children=10-3 65.00 ± 0% 66.00 ± 0% +1.54% (p=0.002 n=6)
GatherMetricVec/gauge/children=900-3 3.648k ± 0% 3.649k ± 0% +0.03% (p=0.002 n=6)
GatherMetricVec/gauge/children=2000-3 8.059k ± 0% 8.060k ± 0% +0.01% (p=0.002 n=6)
GatherMetricVec/gauge/children=5000-3 20.08k ± 0% 20.08k ± 0% +0.00% (p=0.002 n=6)
GatherMetricVec/histogram/children=10-3 305.0 ± 0% 306.0 ± 0% +0.33% (p=0.002 n=6)
GatherMetricVec/histogram/children=900-3 25.25k ± 0% 25.25k ± 0% +0.00% (p=0.002 n=6)
GatherMetricVec/histogram/children=2000-3 56.06k ± 0% 56.06k ± 0% +0.00% (p=0.002 n=6)
GatherMetricVec/histogram/children=5000-3 140.1k ± 0% 140.1k ± 0% +0.00% (p=0.002 n=6)
geomean 6.247k 6.262k +0.24%
There was a problem hiding this comment.
Gather on a copy of our production /metrics page (426 vectors, 17 957 children, 33k series), linux/arm64, 4 cores, go1.26, -count=6:
| main | PR #2157 | delta | |
|---|---|---|---|
| Gather time | 11.86 ms | 12.17 ms | +0.3 ms, +2.6% (noise is ±10%) |
| B/op | 6.82 MiB | 7.11 MiB | +300 KiB, +4.3% |
| allocs/op | 104 470 | 104 633 | +163 |
single-vector benchmark is the worst case because Gather idles while the only vector builds its snapshot. On a real page Gather consumes metrics from other collectors meanwhile, so the time cost drops to a few percent.
Allocations are +163 and not +426. I think this is because since Go 1.25 a variable-size make of up to 32 bytes is stack-allocated, so vectors with one or two children do not allocate at all.
Signed-off-by: lif0 <22912194+lif0@users.noreply.github.com>
|
merged main into my branch |
2 participants
Summary
This PR changes Collect. It copies the children into a slice under the read lock, releases the lock, and only then sends them. This is the solution proposed in the issue.
The cost is one temporary slice with the size of the vector per Collect.
A child that is deleted or reset after the snapshot can still be sent once in this Collect. Delete and Reset no longer wait for a slow consumer.
A stuck scrape still makes the metrics unavailable, but the process keeps working.
Fixes Registry.Gather: a blocked Metric.Write keeps vec RLock and blocks all WithLabelValues calls #2147
Regression test
TestMetricVecCollectWithBlockedGathercreates a MetricVec with 2000 children. This is more than the Gather channel can buffer. The Metric.Write of these children blocks until the test releases it. The test starts Gather and waits until it is inside Write. Then it checks that creating a new child and reading an existing child both return. Without the fix the test fails with this error.Benchmarks
Run with
go test -count=6 -benchmemon linux/arm64.The fix adds exactly one allocation per Collect (65 -> 66 and 8059 -> 8060 allocs/op) and 16 bytes per child (+32 KiB per Gather for 2000 children).