Mikhail Khludnev created SOLR-18442:
---------------------------------------
Summary: 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: 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*).
## 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.
## 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:
> Reference walk on those arrays:
>
> long[] <- 2,604 FixedBitSet <- 3,887 FixedBits <- SegmentReader
>
> `FixedBits` is what `SegmentReader.getLiveDocs()` returns. These are
> live-docs bitsets [...]
> ~650 retained copies of every segment's deletion mask.
The arrays came in four sizes, one per segment in the index, each retained ~650
times. Walking up
from the searcher:
> Who holds them
>
> 1,812 org.apache.solr.search.SolrIndexSearcher
> 1,815 org.apache.lucene.index.StandardDirectoryReader
> 5,678 org.apache.lucene.index.SegmentReader
>
> Reference walk from SolrIndexSearcher upward:
>
> SolrIndexSearcher
> <- SolrIndexSearcher$$Lambda (a gauge callback)
> <- InstrumentBuilder$$Lambda
> <- 1,974
> io.opentelemetry.sdk.metrics.internal.state.CallbackRegistration
>
> 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.
That last point is the crux: **`SolrCore` holds 6 searchers; the OTel registry
holds ~1,800.**
## 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`:
```
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
```
`hist2.txt`, same process, +10 minutes:
```
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
```
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.
## Where the retention comes from
`SolrIndexSearcher` takes a child metrics context and registers gauges on it:
```java
// SolrIndexSearcher.java:607
this.solrMetricsContext = core.getSolrMetricsContext().getChildContext(this);
...
// SolrIndexSearcher.java:616
initializeMetrics(solrMetricsContext, core.getCoreAttributes());
```
The callbacks capture `reader` directly, so one surviving registration pins an
entire
`DirectoryReader` and everything under it:
```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));
```
(the same shape at `:2372`, `:2382`, and `observableDoubleGauge` at `:2392`).
The teardown path exists and is documented as exactly this defence:
```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());
}
```
```java
// SolrMetricsContext.java:282
public void close() {
assert ObjectReleaseTracker.release(this);
IOUtils.closeQuietly(closeables);
closeables.clear();
}
```
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.
## No way to disable it
`<metrics enabled="false"/>` in `solr.xml` does **not** stop this. That flag
only short-circuits
the suppliers and reporters:
```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();
}
```
and the only consumer of the resulting config is the reporter list:
```java
// CoreContainer.java:913
PluginInfo[] metricReporters = cfg.getMetricsConfig().getMetricReporters();
```
The registration path never consults the flag — `SolrMetricManager` contains no
reference to it at
all, and goes straight to the meter:
```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);
}
```
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.
## Related gap worth fixing in the same change
`SolrMetricsContext` registers a closeable only in the **3-argument** overloads:
```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);
}
```
`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]
