You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@solr.apache.org by michael dürr <du...@gmail.com> on 2023/07/11 12:24:30 UTC
Metrics api calls causing blocking threads during indexing
Hi,
I recently observed that calls to the metrics api get stuck (thread state
waiting) when we call it for an index that is built from scratch. This
became a problem when we used the solr metrics exporter and unexpectedly
ran out of memory due to the accumulating threads.
This is one of the waiting thread's stacktrace (collected by the
solr/admin/info/threads
endpoint):
{
"id": 28,
"name": "qtp2085745483-28",
"state": "WAITING",
"lock": "java.lang.Object@6665e80c",
"lock-waiting": {
"name": "java.lang.Object@6665e80c",
"owner": null
},
"cpuTime": "96040.3276ms",
"userTime": "95230.0000ms",
"stackTrace": [
"java.base@17.0.6/java.lang.Object.wait(Native Method)",
"java.base@17.0.6/java.lang.Object.wait(Object.java:338)",
"org.apache.solr.core.SolrCore.getSearcher(SolrCore.java:2528)",
"org.apache.solr.core.SolrCore.getSearcher(SolrCore.java:2271)",
"org.apache.solr.core.SolrCore.getSearcher(SolrCore.java:2106)",
"org.apache.solr.core.SolrCore.withSearcher(SolrCore.java:2124)",
"org.apache.solr.core.SolrCore.getSegmentCount(SolrCore.java:534)",
"org.apache.solr.core.SolrCore.lambda$initializeMetrics$11(SolrCore.java:1360)",
"org.apache.solr.core.SolrCore$$Lambda$715/0x0000000801692620.getValue(Unknown
Source)",
"org.apache.solr.util.stats.MetricUtils.convertGauge(MetricUtils.java:825)",
"org.apache.solr.util.stats.MetricUtils.convertMetric(MetricUtils.java:493)",
"org.apache.solr.util.stats.MetricUtils.lambda$toMaps$6(MetricUtils.java:351)",
"org.apache.solr.util.stats.MetricUtils$$Lambda$1360/0x000000080187a0c0.accept(Unknown
Source)",
"java.base@17.0.6
/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)",
"java.base@17.0.6
/java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:179)",
"java.base@17.0.6
/java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:179)",
"java.base@17.0.6
/java.util.TreeMap$KeySpliterator.forEachRemaining(TreeMap.java:3064)",
"java.base@17.0.6
/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509)",
"java.base@17.0.6
/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499)",
"java.base@17.0.6
/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)",
"java.base@17.0.6
/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)",
"java.base@17.0.6
/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)",
"java.base@17.0.6
/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:596)",
"org.apache.solr.util.stats.MetricUtils.toMaps(MetricUtils.java:348)",
"org.apache.solr.handler.admin.MetricsHandler.handleExprRequest(MetricsHandler.java:227)",
"org.apache.solr.handler.admin.MetricsHandler.handleRequest(MetricsHandler.java:133)",
"org.apache.solr.handler.admin.MetricsHandler.handleRequestBody(MetricsHandler.java:113)",
"org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:224)",
"org.apache.solr.servlet.HttpSolrCall.handleAdmin(HttpSolrCall.java:929)",
"org.apache.solr.servlet.HttpSolrCall.handleAdminRequest(HttpSolrCall.java:877)",
"org.apache.solr.servlet.HttpSolrCall.call(HttpSolrCall.java:548)",
"org.apache.solr.servlet.SolrDispatchFilter.dispatch(SolrDispatchFilter.java:252)",
"org.apache.solr.servlet.SolrDispatchFilter.lambda$doFilter$0(SolrDispatchFilter.java:220)",
"org.apache.solr.servlet.SolrDispatchFilter$$Lambda$1168/0x00000008017ecef0.run(Unknown
Source)",
"org.apache.solr.servlet.ServletUtils.traceHttpRequestExecution2(ServletUtils.java:257)",
"org.apache.solr.servlet.ServletUtils.rateLimitRequest(ServletUtils.java:227)",
"org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:215)",
"org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:197)",
"org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:210)",
"org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1635)",
"org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:527)",
"org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:131)",
"org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:578)",
"org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)",
"org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:223)",
"org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1570)",
"org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:221)",
"org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1383)",
"org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:176)",
"org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:484)",
"org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1543)",
"org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:174)",
"org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1305)",
"org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:129)",
"org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:149)",
"org.eclipse.jetty.server.handler.InetAccessHandler.handle(InetAccessHandler.java:228)",
"org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:141)",
"org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)",
"org.eclipse.jetty.rewrite.handler.RewriteHandler.handle(RewriteHandler.java:301)",
"org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)",
"org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:822)",
"org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)",
"org.eclipse.jetty.server.Server.handle(Server.java:563)",
"org.eclipse.jetty.server.HttpChannel.lambda$handle$0(HttpChannel.java:505)",
"org.eclipse.jetty.server.HttpChannel$$Lambda$1113/0x00000008017c8200.dispatch(Unknown
Source)",
"org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:762)",
"org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:497)",
"org.eclipse.jetty.server.HttpChannel.run(HttpChannel.java:457)",
"org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:416)",
"org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:385)",
"org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:272)",
"org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.produce(AdaptiveExecutionStrategy.java:194)",
"org.eclipse.jetty.http2.HTTP2Connection.produce(HTTP2Connection.java:208)",
"org.eclipse.jetty.http2.HTTP2Connection.onFillable(HTTP2Connection.java:155)",
"org.eclipse.jetty.http2.HTTP2Connection$FillableCallback.succeeded(HTTP2Connection.java:378)",
"org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:100)",
"org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53)",
"org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:416)",
"org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:385)",
"org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:272)",
"org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.lambda$new$0(AdaptiveExecutionStrategy.java:140)",
"org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy$$Lambda$383/0x0000000800f96a90.run(Unknown
Source)",
"org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:411)",
"org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:934)",
"org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1078)",
"java.base@17.0.6/java.lang.Thread.run(Thread.java:833)"
]
}
The metrics call causing this:
/solr/admin/metrics?expr=solr\.core\..*:INDEX\..*
Shall I open a jira issue for this?
Thanks,
Michael
Re: Metrics api calls causing blocking threads during indexing
Posted by michael dürr <du...@gmail.com>.
Hi Shawn,
The thread dump was generated on our production systems under high load. As
this state caused OOMs I'll try to reproduce that case in our testing
environment.
I'll report as soon as I can reproduce that situation there.
Thanks,
Michael
On Wed, Jul 12, 2023 at 4:38 PM Shawn Heisey <ap...@elyograg.org> wrote:
> On 7/11/23 21:50, michael dürr wrote:
> > The solr version I'm running is 9.2.1 and it is not customized (not
> > compiled from source).
> >
> > I scanned the whole stack trace for that object reference, but could only
> > find threads that state that they are waiting for that lock as well. What
> > exactly is the pattern I have to look for?
> > The only stack trace that differs from that I posted before is this one
> > (all other threads waiting for that lock have the "same" stacktrace as it
> > was the same metrics call that caused their creation):
>
> It looks like Solr's thread dump handler does not include the info
> required to cross-reference a lock. So that handler that returns a
> thread dump needs a little more detail added to it. I can't look at it
> today, that will need to wait until tomorrow.
>
> In the meantime, if you have Java itself generate a thread dump, then
> that should contain the info required to cross reference the lock and
> see what thread is holding the lock.
>
> Thanks,
> Shawn
>
Re: Metrics api calls causing blocking threads during indexing
Posted by Shawn Heisey <ap...@elyograg.org>.
On 7/11/23 21:50, michael dürr wrote:
> The solr version I'm running is 9.2.1 and it is not customized (not
> compiled from source).
>
> I scanned the whole stack trace for that object reference, but could only
> find threads that state that they are waiting for that lock as well. What
> exactly is the pattern I have to look for?
> The only stack trace that differs from that I posted before is this one
> (all other threads waiting for that lock have the "same" stacktrace as it
> was the same metrics call that caused their creation):
It looks like Solr's thread dump handler does not include the info
required to cross-reference a lock. So that handler that returns a
thread dump needs a little more detail added to it. I can't look at it
today, that will need to wait until tomorrow.
In the meantime, if you have Java itself generate a thread dump, then
that should contain the info required to cross reference the lock and
see what thread is holding the lock.
Thanks,
Shawn
Re: Metrics api calls causing blocking threads during indexing
Posted by michael dürr <du...@gmail.com>.
Hi Shawn,
The solr version I'm running is 9.2.1 and it is not customized (not
compiled from source).
I scanned the whole stack trace for that object reference, but could only
find threads that state that they are waiting for that lock as well. What
exactly is the pattern I have to look for?
The only stack trace that differs from that I posted before is this one
(all other threads waiting for that lock have the "same" stacktrace as it
was the same metrics call that caused their creation):
{
"id": 65,
"name": "coreLoadExecutor-18-thread-1-processing-192.168.0.223:8983_solr",
"state": "WAITING",
"lock": "java.lang.Object@6665e80c",
"lock-waiting": {
"name": "java.lang.Object@6665e80c",
"owner": null
},
"synchronizers-locked": [
"java.util.concurrent.ThreadPoolExecutor$Worker@17d83fe4"
],
"cpuTime": "359.5291ms",
"userTime": "330.0000ms",
"stackTrace": [
"java.base@17.0.6/java.lang.Object.wait(Native Method)",
"java.base@17.0.6/java.lang.Object.wait(Object.java:338)",
"org.apache.solr.core.SolrCore.getSearcher(SolrCore.java:2528)",
"org.apache.solr.core.SolrCore.initSearcher(SolrCore.java:1283)",
"org.apache.solr.core.SolrCore.<init>(SolrCore.java:1168)",
"org.apache.solr.core.SolrCore.<init>(SolrCore.java:1051)",
"org.apache.solr.core.CoreContainer.createFromDescriptor(CoreContainer.java:1666)",
"org.apache.solr.core.CoreContainer.lambda$load$12(CoreContainer.java:1015)",
"org.apache.solr.core.CoreContainer$$Lambda$545/0x00000008015bf2f0.call(Unknown
Source)",
"com.codahale.metrics.InstrumentedExecutorService$InstrumentedCallable.call(InstrumentedExecutorService.java:234)",
"java.base@17.0.6
/java.util.concurrent.FutureTask.run(FutureTask.java:264)",
"org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:289)",
"org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor$$Lambda$256/0x0000000800e4fd48.run(Unknown
Source)",
"java.base@17.0.6
/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)",
"java.base@17.0.6
/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)",
"java.base@17.0.6/java.lang.Thread.run(Thread.java:833)"
]
}
Is there anything else I can provide?
Thanks,
Michael
On Wed, Jul 12, 2023 at 1:13 AM Shawn Heisey <ap...@elyograg.org> wrote:
> On 7/11/23 06:24, michael dürr wrote:
> > I recently observed that calls to the metrics api get stuck (thread state
> > waiting) when we call it for an index that is built from scratch. This
> > became a problem when we used the solr metrics exporter and unexpectedly
> > ran out of memory due to the accumulating threads.
> >
> > This is one of the waiting thread's stacktrace (collected by the
> > solr/admin/info/threads
> > endpoint):
> >
> > {
> > "id": 28,
> > "name": "qtp2085745483-28",
> > "state": "WAITING",
> > "lock": "java.lang.Object@6665e80c",
>
> This thread is waiting for the lock on 'java.lang.Object@6665e80c' to be
> released. You would need to look through the rest of the threads to see
> what thread is holding that lock, then we need the exact version of Solr
> you're running and the stacktrace of that thread so we can look at the
> source code to see what might be wrong.
>
> If you are running a customized version of Solr that was compiled from
> source, it might be necessary to have access to the customized source code.
>
> Thanks,
> Shawn
>
Re: Metrics api calls causing blocking threads during indexing
Posted by Shawn Heisey <ap...@elyograg.org>.
On 7/11/23 06:24, michael dürr wrote:
> I recently observed that calls to the metrics api get stuck (thread state
> waiting) when we call it for an index that is built from scratch. This
> became a problem when we used the solr metrics exporter and unexpectedly
> ran out of memory due to the accumulating threads.
>
> This is one of the waiting thread's stacktrace (collected by the
> solr/admin/info/threads
> endpoint):
>
> {
> "id": 28,
> "name": "qtp2085745483-28",
> "state": "WAITING",
> "lock": "java.lang.Object@6665e80c",
This thread is waiting for the lock on 'java.lang.Object@6665e80c' to be
released. You would need to look through the rest of the threads to see
what thread is holding that lock, then we need the exact version of Solr
you're running and the stacktrace of that thread so we can look at the
source code to see what might be wrong.
If you are running a customized version of Solr that was compiled from
source, it might be necessary to have access to the customized source code.
Thanks,
Shawn