[
https://issues.apache.org/jira/browse/SOLR-18442?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=18116433#comment-18116433
]
Chris M. Hostetter commented on SOLR-18442:
-------------------------------------------
A couple of observations...
# Applying *only* the {{SolrIndexSearcherTest.java}} changes from Mikhail's
PR#4902, i can reproduce the test failures *ON 10x*
** _applying the same changes to 10.0.0 does not reproduce the test failure_ -
most likely because the way the "closing" of metric changes has changed on 10x
(and main) since 10.0.0 was released
** in 10.0.0 SolrIndexSearcher kept track of it's own list of gauges
{{toClose}}
** on 10x, the the "closing" responsibility was moved into
{{SolrMetricsContext}} – where the "4 arg" gauges have the bug fixed by Jan's
pr#4917
*** confirmed by applying *BOTH* Michal's {{SolrIndexSearcherTest.java}}
changes with Jan's PR fixing SolrMetricsContext
# the lack of test failure reproducibility on 10.0.0 makes it *seem* like
"this bug" does not affect 10.0.0 ... but...
** manual testing of 10.0.0 does indicates that there *IS* metric object
leakage with repeated cycles of indexing/quering
** the problem is less severe (not full {{SolrIndexSearcher}} objects being
leaked, but smaller {{io.opentelemetry.sdk.metrics.internal.state}} do seem to
grow w/o bounds
# this makes me concerned that there may in fact be *TWO* distinct memory
leaks related to metrics object lifecycles
** one big one, leaking entire SolrIndexSearcher objects, that _does not_
affect 10.0.0
*** definitely fixed by Jan's patch
** one smaller one, leaking smaller metric objects that *DOES affect 10.0.0*
*** exact origin unknown, but *ALSO* seems to be fixed by jan's patch
----
steps to reproduce the "smaller leak" on 10.0.0...
{noformat}
### Run the following 3 commands (starting them in this order, a few seconds
apart) concurrently in distinct terminals..
docker run --rm -it -p 8983:8983 solr:10.0.0 solr-demo
while true; do sudo /opt/jdk/21/latest//bin/jcmd $(pgrep -U 8983 java)
GC.class_histogram | grep "SdkObservableMeasurement\$"; sleep 5; done
for i in {1000..2000}; do curl -sS
'http://localhost:8983/solr/demo/update/json/docs?commit=true' --data-binary
"{\"id\":\"hoss${i}\"}" > /dev/null; curl -sS
'http://localhost:8983/solr/demo/select?q=*:*' > /dev/null && curl -sS
'http://localhost:8983/solr/admin/metrics' > /dev/null; echo "$i"; done
{noformat}
output of the {{GC.class_histogram}} calls ...
{noformat}
339: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
339: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
339: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
351: 105 3360
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
269: 161 5152
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
221: 225 7200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
191: 292 9344
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
170: 360 11520
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
157: 431 13792
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
142: 500 16000
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
124: 568 18176
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
114: 637 20384
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
110: 707 22624
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
103: 773 24736
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
95: 841 26912
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
94: 909 29088
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
92: 978 31296
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
90: 1049 33568
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
87: 1101 35232
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
87: 1101 35232
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
87: 1101 35232
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
87: 1101 35232
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
87: 1101 35232
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
{noformat}
Note that the count levels off forever once index+query for loop ends (even if
you manually keep fetching /solr/admin/metrics)
If you run those same commands, using a {{apache/solr:10.1.0-SNAPSHOT}} built
from 10x, with Jan's patch...
{noformat}
336: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
336: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
351: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
349: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
354: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
350: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
350: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
351: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
354: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
351: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
354: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
350: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
351: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
355: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
351: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
351: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
351: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
355: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
355: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
355: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
354: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
354: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
354: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
354: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
354: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
354: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
354: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
354: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
354: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
354: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
354: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
354: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
354: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
354: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
354: 100 3200
io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement {noformat}
> SolrIndexSearcher is retained for the life of the node by OpenTelemetry
> observable gauges
> -----------------------------------------------------------------------------------------
>
> Key: SOLR-18442
> URL: https://issues.apache.org/jira/browse/SOLR-18442
> Project: Solr
> Issue Type: Bug
> Components: metrics
> Affects Versions: 10.0, main(11.0)
> Environment: - Solr 11.0.0-SNAPSHOT (`solr-11.0.0-SNAPSHOT-slim`)
> - OpenJDK 21.0.12+8, `-Xmx2g -XX:+UseG1GC`
> - 3 cores, sustained indexing with frequent commits
> Reporter: Mikhail Khludnev
> Priority: Critical
> Labels: pull-request-available
> Time Spent: 1h 40m
> Remaining Estimate: 0h
>
> Every {{SolrIndexSearcher}} registers observable gauges whose callbacks
> capture the searcher's {{DirectoryReader}}. Those registrations are never
> removed, so the OpenTelemetry meter holds one {{CallbackRegistration}} per
> searcher ever opened -- and through it the searcher, its {{DirectoryReader}},
> every {{SegmentReader}}, and every segment's live-docs bitset. {{SolrCore}}
> has already released these searchers; the metric registry is the only thing
> still referencing them.
> The leak is proportional to the searcher open rate, so any node with a high
> commit cadence runs out of heap. There is no configuration that turns it off
> (see _No way to disable it_).
> h2. Symptom
> A node under sustained commit load fills the heap and dies with {{fatal
> error: OutOfMemory encountered: Java heap space}}, with GC pause times
> healthy throughout (p50 4.5-9.3 ms) -- the collector is fine, the live set
> simply grows without bound.
> h2. Evidence 1 -- heap dump: what fills the heap and who holds it
> From a 2.1 GB heap dump taken at OOM, walking references up from the largest
> arrays:
> {quote}
> Reference walk on those arrays:
> {noformat}
> long[] <- 2,604 FixedBitSet <- 3,887 FixedBits <- SegmentReader
> {noformat}
> {{FixedBits}} is what {{SegmentReader.getLiveDocs()}} returns. These are
> live-docs bitsets \[...\] ~650 retained copies of every segment's deletion
> mask.
> {quote}
> The arrays came in four sizes, one per segment in the index, each retained
> ~650 times. Walking up from the searcher:
> {quote}
> Who holds them
> {noformat}
> 1,812 org.apache.solr.search.SolrIndexSearcher
> 1,815 org.apache.lucene.index.StandardDirectoryReader
> 5,678 org.apache.lucene.index.SegmentReader
> {noformat}
> Reference walk from SolrIndexSearcher upward:
> {noformat}
> SolrIndexSearcher
> <- SolrIndexSearcher$$Lambda (a gauge callback)
> <- InstrumentBuilder$$Lambda
> <- 1,974 io.opentelemetry.sdk.metrics.internal.state.CallbackRegistration
> {noformat}
> 1,974 callback registrations pinning 1,962 searchers. And {{SolrCore}} (3
> instances) references only 6 searchers -- 2 per core -- so Solr itself has
> already let go of the rest. The only thing still holding ~1,800 searchers,
> their readers, and every segment's live-docs bitset is the OpenTelemetry
> metric registry.
> {quote}
> That last point is the crux: *{{SolrCore}} holds 6 searchers; the OTel
> registry holds ~1,800.*
> h2. Evidence 2 -- live histogram, two samples ten minutes apart
> {{jcmd <pid> GC.class_histogram}} (which forces a full GC, so these are live
> objects only), taken twice ten minutes apart on the same process:
> {{hist1.txt}}:
> {noformat}
> 34648:
> num #instances #bytes class name (module)
> -------------------------------------------------------
> 1: 6045 39075104 [J ([email protected])
> ...
> 252: 48 9216 org.apache.solr.search.SolrIndexSearcher
> 305: 48 6528 org.apache.solr.search.CaffeineCache
> 309: 202 6464
> io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
> 344: 159 5088
> io.opentelemetry.sdk.metrics.internal.state.CallbackRegistration
> 421: 51 3672
> org.apache.lucene.index.StandardDirectoryReader
> 473: 117 2808 org.apache.lucene.util.FixedBitSet
> 189: 179 14320 org.apache.lucene.index.SegmentReader
> {noformat}
> {{hist2.txt}}, same process, +10 minutes:
> {noformat}
> 1: 13288 608797408 [J ([email protected])
> 78: 671 128832 org.apache.solr.search.SolrIndexSearcher
> 96: 671 91256 org.apache.solr.search.CaffeineCache
> 190: 825 26400
> io.opentelemetry.sdk.metrics.internal.state.SdkObservableMeasurement
> 195: 782 25024
> io.opentelemetry.sdk.metrics.internal.state.CallbackRegistration
> 131: 674 48528
> org.apache.lucene.index.StandardDirectoryReader
> 153: 1538 36912 org.apache.lucene.util.FixedBitSet
> 66: 2239 179120 org.apache.lucene.index.SegmentReader
> {noformat}
> The deltas move in exact lockstep -- one new searcher, one new callback
> registration, nothing released:
> ||class||hist1||hist2||delta||
> |{{SolrIndexSearcher}}|48|671|*+623*|
> |{{StandardDirectoryReader}}|51|674|*+623*|
> |{{CaffeineCache}}|48|671|*+623*|
> |{{CallbackRegistration}}|159|782|*+623*|
> |{{SdkObservableMeasurement}}|202|825|*+623*|
> |{{SolrIndexSearcher$$Lambda/0x...d878}}|48|671|*+623*|
> |{{SegmentReader}}|179|2,239|+2,060|
> |{{FixedBitSet}}|117|1,538|+1,421|
> Total live heap over those ten minutes: *96 MB -> 706 MB*, of which {{[J}}
> (the live-docs bitsets) is 39 MB -> 609 MB.
> h2. Where the retention comes from
> {{SolrIndexSearcher}} takes a child metrics context and registers gauges on
> it:
> {code:java}
> // SolrIndexSearcher.java:607
> this.solrMetricsContext = core.getSolrMetricsContext().getChildContext(this);
> ...
> // SolrIndexSearcher.java:616
> initializeMetrics(solrMetricsContext, core.getCoreAttributes());
> {code}
> The callbacks capture {{reader}} directly, so one surviving registration pins
> an entire {{DirectoryReader}} and everything under it:
> {code:java}
> // SolrIndexSearcher.java:2361
> solrMetricsContext.observableLongGauge(
> "solr.core.indexsearcher.index.num_docs",
> "Number of live docs in the index",
> obs -> obs.record(reader.numDocs(), baseAttributes));
> {code}
> (the same shape at {{:2372}}, {{:2382}}, and {{observableDoubleGauge}} at
> {{:2392}}).
> The teardown path exists and is documented as exactly this defence:
> {code:java}
> // SolrMetricProducer.java:73-85
> // * Implementations should always call SolrMetricProducer.super.close() to
> ensure that
> // * metrics with the same life-cycle as this component are properly
> unregistered. This
> // * prevents obscure memory leaks.
> default void close() throws IOException {
> IOUtils.closeQuietly(getSolrMetricsContext());
> }
> {code}
> {code:java}
> // SolrMetricsContext.java:282
> public void close() {
> assert ObjectReleaseTracker.release(this);
> IOUtils.closeQuietly(closeables);
> closeables.clear();
> }
> {code}
> and {{SolrIndexSearcher.close()}} does call {{SolrInfoBean.super.close()}}.
> The heap proves it is not taking effect. *Open question for whoever picks
> this up:* whether {{SolrIndexSearcher.close()}} never runs for these
> searchers, or whether closing the OTel handle does not drop the
> {{CallbackRegistration}}. A dump cannot distinguish the two; it needs a live
> experiment.
> h2. No way to disable it
> moved to SOLR-18455
> h2. Related gap worth fixing in the same change
> {{SolrMetricsContext}} registers a closeable only in the *3-argument*
> overloads:
> {code:java}
> // SolrMetricsContext.java:161-166 -- registers
> public ObservableLongGauge observableLongGauge(
> String metricName, String description,
> Consumer<ObservableLongMeasurement> callback) {
> var observableLongGauge = observableLongGauge(metricName, description,
> callback, null);
> closeables.add(observableLongGauge);
> return observableLongGauge;
> }
> // SolrMetricsContext.java:168-173 -- does NOT register
> public ObservableLongGauge observableLongGauge(
> String metricName, String description,
> Consumer<ObservableLongMeasurement> callback, OtelUnit unit) {
> return metricManager.observableLongGauge(registryName, metricName,
> description, callback, unit);
> }
> {code}
> {{observableDoubleGauge}} has the same asymmetry. {{SolrIndexSearcher}}'s own
> gauges use the 3-arg form, so this is not the cause of _this_ leak -- but any
> caller that passes an {{OtelUnit}} gets a registration that
> {{SolrMetricsContext.close()}} can never release.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
