[
https://issues.apache.org/jira/browse/SOLR-18442?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Andrzej Bialecki updated SOLR-18442:
------------------------------------
Affects Version/s: 10.0
(was: 10.1)
> 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: Major
>
> 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
> {{<metrics enabled="false"/>}} in {{solr.xml}} does *not* stop this. That
> flag only short-circuits the suppliers and reporters:
> {code:java}
> // SolrXmlConfig.java:681-688
> private static MetricsConfig getMetricsConfig(ConfigNode metrics) {
> MetricsConfig.MetricsConfigBuilder builder = new
> MetricsConfig.MetricsConfigBuilder();
> boolean enabled = metrics.boolAttr("enabled", true);
> builder.setEnabled(enabled);
> if (!enabled) {
> log.info("Metrics collection is disabled.");
> return builder.build();
> }
> {code}
> and the only consumer of the resulting config is the reporter list:
> {code:java}
> // CoreContainer.java:913
> PluginInfo[] metricReporters = cfg.getMetricsConfig().getMetricReporters();
> {code}
> The registration path never consults the flag -- {{SolrMetricManager}}
> contains no reference to it at all, and goes straight to the meter:
> {code:java}
> // SolrMetricManager.java
> public ObservableLongGauge observableLongGauge(
> String registry, String gaugeName, String description,
> Consumer<ObservableLongMeasurement> callback, OtelUnit unit) {
> return longGaugeBuilder(registry, gaugeName, description,
> unit).buildWithCallback(callback);
> }
> {code}
> This was confirmed empirically: *the histograms above are from a run with
> {{<metrics enabled="false"/>}} applied.* Reporting was off; the instruments
> were still built and still leaked at +623 searchers per ten minutes.
> So an affected node has no configuration escape -- only reducing its commit
> rate, which slows the leak proportionally without stopping it.
> 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]
