[
https://issues.apache.org/jira/browse/SOLR-18442?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=18115146#comment-18115146
]
Andrzej Bialecki commented on SOLR-18442:
-----------------------------------------
FWIW using the fix in PR #4902 the only flakiness I see is the accidental index
pollution in {{SolrIndexSearcherTest}} due to the added doc (the total number
of docs may not match in other methods depending on the method execution order).
The fix to avoid creating registries when metrics are disabled: strictly
speaking this could have been a back-compat break with 10.0 because it would
return nothing instead of a list of metrics ... but "fortunately" it's hitting
the same bug in both versions that throws an IOException :) so I think this
should also be included, with a bugfix for that exception.
> 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]
