CanMatch Running on Transport Thread

[john-wagster]

Elasticsearch Version

main

Installed Plugins

No response

Java Version

bundled

OS Version

all

Problem Description

While investigating a customer issue it was found that from a hot threads dump that canMatch was running on the transport thread. We should probably evaluate if that should instead be running on the search or search_coordination thread.

Specifically on line 731:

CanMatchShardResponse canMatchResp = canMatch(canMatchContext, false);

is being run as part of executeQueryPhase and is left on the transport thread.

It looks like all other usages of this are delegated off to the search_coordination thread:

transportService.registerRequestHandler(
    QUERY_CAN_MATCH_NODE_NAME,
    transportService.getThreadPool().executor(ThreadPool.Names.SEARCH_COORDINATION),
    CanMatchNodeRequest::new,
    (request, channel, task) -> searchService.canMatch(request, new ChannelActionListener<>(channel))
);

Steps to Reproduce

We found this in the context of PIT queries that were running. I haven't tried to reproduce locally but I can if it would be helpful.

Logs (if relevant)

Here's a dump of the stack

   13.1% [cpu=13.1%, idle=83.7%] (484ms out of 500ms) cpu usage by thread 'elasticsearch[instance-0000000127][transport_worker][T#3]'
     9/10 snapshots sharing following 10 elements
       java.base@24/sun.nio.ch.EPoll.wait(Native Method)
       java.base@24/sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:117)
       java.base@24/sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:130)
       java.base@24/sun.nio.ch.SelectorImpl.select(SelectorImpl.java:147)
       io.netty.transport@4.1.118.Final/io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:887)
       io.netty.transport@4.1.118.Final/io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:526)
       io.netty.common@4.1.118.Final/io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:998)
       io.netty.common@4.1.118.Final/io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
       java.base@24/java.lang.Thread.runWith(Thread.java:1460)
       java.base@24/java.lang.Thread.run(Thread.java:1447)
     unique snapshot
       app/org.apache.lucene.core@9.12.1/org.apache.lucene.index.CodecReader.getPointValues(CodecReader.java:228)
       app/org.apache.lucene.core@9.12.1/org.apache.lucene.index.FilterLeafReader.getPointValues(FilterLeafReader.java:346)
       app/org.apache.lucene.core@9.12.1/org.apache.lucene.index.FilterLeafReader.getPointValues(FilterLeafReader.java:346)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.search.internal.FieldUsageTrackingDirectoryReader$FieldUsageTrackingLeafReader.getPointValues(FieldUsageTrackingDirectoryReader.java:132)
       app/org.apache.lucene.core@9.12.1/org.apache.lucene.index.PointValues.getMinPackedValue(PointValues.java:158)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.index.mapper.DateFieldMapper$DateFieldType.isFieldWithinQuery(DateFieldMapper.java:778)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.index.query.RangeQueryBuilder.getRelation(RangeQueryBuilder.java:484)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.index.query.RangeQueryBuilder.doSearchRewrite(RangeQueryBuilder.java:503)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.index.query.AbstractQueryBuilder.doRewrite(AbstractQueryBuilder.java:319)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.index.query.AbstractQueryBuilder.rewrite(AbstractQueryBuilder.java:290)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.index.query.BoolQueryBuilder.rewriteClauses(BoolQueryBuilder.java:402)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.index.query.BoolQueryBuilder.doRewrite(BoolQueryBuilder.java:356)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.index.query.AbstractQueryBuilder.rewrite(AbstractQueryBuilder.java:290)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.search.builder.SubSearchSourceBuilder.rewrite(SubSearchSourceBuilder.java:90)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.search.builder.SubSearchSourceBuilder.rewrite(SubSearchSourceBuilder.java:38)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.index.query.Rewriteable.rewrite(Rewriteable.java:57)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.index.query.Rewriteable.rewrite(Rewriteable.java:40)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.index.query.Rewriteable.rewrite(Rewriteable.java:125)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.search.builder.SearchSourceBuilder.rewrite(SearchSourceBuilder.java:1187)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.search.builder.SearchSourceBuilder.rewrite(SearchSourceBuilder.java:92)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.index.query.Rewriteable.rewrite(Rewriteable.java:57)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.index.query.Rewriteable.rewrite(Rewriteable.java:40)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.search.internal.ShardSearchRequest$RequestRewritable.rewrite(ShardSearchRequest.java:588)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.search.internal.ShardSearchRequest$RequestRewritable.rewrite(ShardSearchRequest.java:577)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.index.query.Rewriteable.rewrite(Rewriteable.java:57)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.search.SearchService.queryStillMatchesAfterRewrite(SearchService.java:1973)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.search.SearchService.canMatch(SearchService.java:1949)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.search.SearchService.lambda$executeQueryPhase$6(SearchService.java:648)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.search.SearchService$$Lambda/0x0000000032cf2908.accept(Unknown Source)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.action.ActionListenerImplementations$DelegatingFailureActionListener.onResponse(ActionListenerImplementations.java:219)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.action.ActionListenerImplementations$SafeMappedActionListener.onResponse(ActionListenerImplementations.java:131)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.index.query.Rewriteable.rewriteAndFetch(Rewriteable.java:109)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.index.query.Rewriteable.rewriteAndFetch(Rewriteable.java:77)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.search.SearchService.rewriteAndFetchShardRequest(SearchService.java:2004)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.search.SearchService.executeQueryPhase(SearchService.java:636)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.action.search.SearchTransportService.lambda$registerRequestHandler$6(SearchTransportService.java:474)
       app/org.elasticsearch.server@8.18.4/org.elasticsearch.action.search.SearchTransportService$$Lambda/0x0000000032308000.messageReceived(Unknown Source)

[elasticsearchmachine]

Pinging @elastic/es-search-foundations (Team:Search Foundations)

[javanna]

Good catch, we should fork this to either search or search coord.

[benwtrent]

EDIT: this is a separate transport_worker issue around searchShards sorting

Here is an example trace that can block. This gets expensive over 10s of thousands of shards.

I also think auth handling is being done in can_match, and if there are complicated roles, yikes.

100.3% [cpu=100.3%, idle=0.0%] (501.4ms out of 500ms) cpu usage by thread 'elasticsearch[instance-0000000279][transport_worker][T#6]'
  2/10 snapshots sharing following 292 elements
    app/org.apache.lucene.core@9.12.0/org.apache.lucene.util.TimSorter.sort(TimSorter.java:203)
    app/org.apache.lucene.core@9.12.0/org.apache.lucene.util.CollectionUtil.timSort(CollectionUtil.java:186)
    app/org.apache.lucene.core@9.12.0/org.apache.lucene.util.CollectionUtil.timSort(CollectionUtil.java:200)
    app/org.elasticsearch.server@8.17.9/org.elasticsearch.cluster.routing.GroupShardsIterator.sortAndCreate(GroupShardsIterator.java:33)
    app/org.elasticsearch.server@8.17.9/org.elasticsearch.cluster.routing.OperationRouting.searchShards(OperationRouting.java:140)
    app/org.elasticsearch.server@8.17.9/org.elasticsearch.action.search.TransportSearchAction.getLocalShardsIterator(TransportSearchAction.java:1840)
[...]

[javanna]

@benwtrent the stack trace you posted seems like a different one compared what was posted in the description of this issue. This last one is from a coordinating node ( I do not even get the connection with can match, is there any?). The initial one is from can match executed as part of of the query phase within a shard (data node). Could you clarify that discrepancy? Am I missing something?

[benwtrent]

@javanna ah, I copied the wrong one :(. My bad

[javanna]

@benwtrent I think search shards deserves a separate issue, it is something to look into, but not an oversight like the can match phase, what do you think?

[benwtrent]

#135472