Mikhail Khludnev created SOLR-18455:
---------------------------------------
Summary: <metrics enabled=false> is too shallow
Key: SOLR-18455
URL: https://issues.apache.org/jira/browse/SOLR-18455
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
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]
