Join query on broker becomes uncancellable #17163

Zeyu-Chen-SFDC · 2024-09-26T00:54:53Z

Long running join query threads on brokers cannot be cancelled or interrupted

Affected Version

28.0.1

Description

Poorly written join queries are seen busy looping in PostJoinCursor.advanceToMatch() on broker's jetty threads. These queries have been running for days. While we have separate efforts to address the queries, we want to release all resources held up on the broker by these joins. When query cancellation is attempted with curl -XDELETE 127.0.0.1:8088/druid/v2/sql/<QID> on the broker, 404 response is returned, and the query thread on the broker continues as before.

Here are some examined internal states of the broker:

From a heap dump of the broker, its SqlLifecycleManager object contains the queryid being cancelled on.
From the same heap dump, the QueryScheduler.queryFutures object does not contain any future under the subject queryid.
The broker is configured with druid.server.http.defaultQueryTimeout=600000
Here is a sample broker jetty thread running this join:

"sql[f09310ef-3547-4a2c-b5c4-b7d23062227e]" #224 daemon prio=5 os_prio=0 tid=0x00007f62b99ce000 nid=0x171 runnable [0x00007f4cee2fb000]
   java.lang.Thread.State: RUNNABLE
	at org.apache.druid.segment.column.TypeSignature.is(TypeSignature.java:127)
	at org.apache.druid.segment.column.Types.is(Types.java:79)
	at org.apache.druid.math.expr.ExpressionTypeConversion.autoDetect(ExpressionTypeConversion.java:58)
	at org.apache.druid.math.expr.BinaryBooleanOpExprBase.eval(BinaryEvalOpExprBase.java:189)
	at org.apache.druid.segment.virtual.RowBasedExpressionColumnValueSelector.eval(RowBasedExpressionColumnValueSelector.java:100)
	at org.apache.druid.segment.virtual.BaseExpressionColumnValueSelector.computeCurrentEval(BaseExpressionColumnValueSelector.java:108)
	at org.apache.druid.segment.virtual.BaseExpressionColumnValueSelector.getObject(BaseExpressionColumnValueSelector.java:77)
	at org.apache.druid.segment.virtual.BaseExpressionColumnValueSelector.getObject(BaseExpressionColumnValueSelector.java:32)
	at org.apache.druid.segment.filter.ExpressionFilter$1.matches(ExpressionFilter.java:147)
	at org.apache.druid.segment.filter.AndFilter$2.matches(AndFilter.java:262)
	at org.apache.druid.segment.join.PostJoinCursor.advanceToMatch(PostJoinCursor.java:81)
	at org.apache.druid.segment.join.PostJoinCursor.wrap(PostJoinCursor.java:68)
	at org.apache.druid.segment.join.HashJoinSegmentStorageAdapter.lambda$makeCursors$1(HashJoinSegmentStorageAdapter.java:342)
	at org.apache.druid.segment.join.HashJoinSegmentStorageAdapter$$Lambda$1843/987186359.apply(Unknown Source)
	at org.apache.druid.java.util.common.guava.Sequences$$Lambda$1101/1086130019.apply(Unknown Source)
	at org.apache.druid.java.util.common.guava.MappingAccumulator.accumulate(MappingAccumulator.java:40)
	at org.apache.druid.java.util.common.guava.BaseSequence.accumulate(BaseSequence.java:44)
	at org.apache.druid.java.util.common.guava.WrappingSequence$1.get(WrappingSequence.java:50)
	at org.apache.druid.java.util.common.guava.SequenceWrapper.wrap(SequenceWrapper.java:55)
	at org.apache.druid.java.util.common.guava.WrappingSequence.accumulate(WrappingSequence.java:45)
	at org.apache.druid.java.util.common.guava.MappedSequence.accumulate(MappedSequence.java:43)
	at org.apache.druid.java.util.common.guava.WrappingSequence$1.get(WrappingSequence.java:50)
	at org.apache.druid.java.util.common.guava.SequenceWrapper.wrap(SequenceWrapper.java:55)
	at org.apache.druid.java.util.common.guava.WrappingSequence.accumulate(WrappingSequence.java:45)
	at org.apache.druid.java.util.common.guava.MappedSequence.accumulate(MappedSequence.java:43)
	at org.apache.druid.java.util.common.guava.ConcatSequence.accumulate(ConcatSequence.java:42)
	at org.apache.druid.java.util.common.guava.WrappingSequence$1.get(WrappingSequence.java:50)
	at org.apache.druid.java.util.common.guava.SequenceWrapper.wrap(SequenceWrapper.java:55)
	at org.apache.druid.java.util.common.guava.WrappingSequence.accumulate(WrappingSequence.java:45)
	at org.apache.druid.query.groupby.epinephelinae.GroupByMergingQueryRunnerV2$1$1$1.call(GroupByMergingQueryRunnerV2.java:252)
	at org.apache.druid.query.groupby.epinephelinae.GroupByMergingQueryRunnerV2$1$1$1.call(GroupByMergingQueryRunnerV2.java:239)
	at com.google.common.util.concurrent.TrustedListenableFutureTask$TrustedFutureInterruptibleTask.runInterruptibly(TrustedListenableFutureTask.java:131)
	at com.google.common.util.concurrent.InterruptibleTask.run(InterruptibleTask.java:74)
	at com.google.common.util.concurrent.TrustedListenableFutureTask.run(TrustedListenableFutureTask.java:82)
	at org.apache.druid.java.util.common.concurrent.DirectExecutorService.execute(DirectExecutorService.java:81)
	at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:134)
	at com.google.common.util.concurrent.AbstractListeningExecutorService.submit(AbstractListeningExecutorService.java:69)
	at org.apache.druid.query.DirectQueryProcessingPool.submitRunnerTask(DirectQueryProcessingPool.java:42)
	at org.apache.druid.query.groupby.epinephelinae.GroupByMergingQueryRunnerV2$1$1.apply(GroupByMergingQueryRunnerV2.java:237)
	at org.apache.druid.query.groupby.epinephelinae.GroupByMergingQueryRunnerV2$1$1.apply(GroupByMergingQueryRunnerV2.java:229)
	at com.google.common.collect.Iterators$6.transform(Iterators.java:829)
	at com.google.common.collect.TransformedIterator.next(TransformedIterator.java:52)
	at com.google.common.collect.Iterators.addAll(Iterators.java:367)
	at com.google.common.collect.Lists.newArrayList(Lists.java:146)
	at com.google.common.collect.Lists.newArrayList(Lists.java:132)
	at org.apache.druid.query.groupby.epinephelinae.GroupByMergingQueryRunnerV2$1.make(GroupByMergingQueryRunnerV2.java:225)
	at org.apache.druid.query.groupby.epinephelinae.GroupByMergingQueryRunnerV2$1.make(GroupByMergingQueryRunnerV2.java:170)
	at org.apache.druid.java.util.common.guava.BaseSequence.toYielder(BaseSequence.java:66)
	at org.apache.druid.java.util.common.guava.LazySequence.toYielder(LazySequence.java:46)
	at org.apache.druid.java.util.common.guava.WrappingSequence$2.get(WrappingSequence.java:88)
	at org.apache.druid.java.util.common.guava.WrappingSequence$2.get(WrappingSequence.java:84)
	at org.apache.druid.java.util.common.guava.SequenceWrapper.wrap(SequenceWrapper.java:55)
	at org.apache.druid.java.util.common.guava.WrappingSequence.toYielder(WrappingSequence.java:83)
	at org.apache.druid.common.guava.CombiningSequence.toYielder(CombiningSequence.java:78)
	at org.apache.druid.java.util.common.guava.LimitedSequence.toYielder(LimitedSequence.java:51)
	at org.apache.druid.java.util.common.guava.YieldingSequenceBase.accumulate(YieldingSequenceBase.java:35)
	at org.apache.druid.java.util.common.guava.WrappingSequence$1.get(WrappingSequence.java:50)
	at org.apache.druid.java.util.common.guava.SequenceWrapper.wrap(SequenceWrapper.java:55)
	at org.apache.druid.java.util.common.guava.WrappingSequence.accumulate(WrappingSequence.java:45)
	at org.apache.druid.java.util.common.guava.MappedSequence.accumulate(MappedSequence.java:43)
	at org.apache.druid.java.util.common.guava.WrappingSequence$1.get(WrappingSequence.java:50)
	at org.apache.druid.query.CPUTimeMetricQueryRunner$1.wrap(CPUTimeMetricQueryRunner.java:77)
	at org.apache.druid.java.util.common.guava.WrappingSequence.accumulate(WrappingSequence.java:45)
	at org.apache.druid.java.util.common.guava.WrappingSequence$1.get(WrappingSequence.java:50)
	at org.apache.druid.java.util.common.guava.SequenceWrapper.wrap(SequenceWrapper.java:55)
	at org.apache.druid.java.util.common.guava.WrappingSequence.accumulate(WrappingSequence.java:45)
	at org.apache.druid.java.util.common.guava.MappedSequence.accumulate(MappedSequence.java:43)
	at org.apache.druid.java.util.common.guava.MappedSequence.accumulate(MappedSequence.java:43)
	at org.apache.druid.server.QueryResultPusher.push(QueryResultPusher.java:148)
	at org.apache.druid.sql.http.SqlResource.doPost(SqlResource.java:121)
	at sun.reflect.GeneratedMethodAccessor180.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60)
	at com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$ResponseOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:205)
	at com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75)
	at com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:302)
	at com.sun.jersey.server.impl.uri.rules.ResourceClassRule.accept(ResourceClassRule.java:108)
	at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)
	at com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:84)
	at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1542)
	at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1473)
	at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1419)
	at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1409)
	at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:409)
	at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:558)
	at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:733)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
	at com.google.inject.servlet.ServletDefinition.doServiceImpl(ServletDefinition.java:286)
	at com.google.inject.servlet.ServletDefinition.doService(ServletDefinition.java:276)
	at com.google.inject.servlet.ServletDefinition.service(ServletDefinition.java:181)
	at com.google.inject.servlet.ManagedServletPipeline.service(ManagedServletPipeline.java:91)
	at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:85)
	at com.google.inject.servlet.ManagedFilterPipeline.dispatch(ManagedFilterPipeline.java:120)
	at com.google.inject.servlet.GuiceFilter.doFilter(GuiceFilter.java:135)
	at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193)
	at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1626)
	at org.apache.druid.server.security.PreResponseAuthorizationCheckFilter.doFilter(PreResponseAuthorizationCheckFilter.java:84)
	at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193)
	at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1626)
	at org.apache.druid.server.initialization.jetty.StandardResponseHeaderFilterHolder$StandardResponseHeaderFilter.doFilter(StandardResponseHeaderFilterHolder.java:164)
	at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193)
	at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1626)
	at org.apache.druid.servlet.filter.SimpleCORSServletFilter.doFilter(SimpleCORSServletFilter.java:42)
	at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193)
	at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1626)
	at org.apache.druid.server.security.AllowHttpMethodsResourceFilter.doFilter(AllowHttpMethodsResourceFilter.java:78)
	at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193)
	at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1626)
	at org.apache.druid.server.security.AllowOptionsResourceFilter.doFilter(AllowOptionsResourceFilter.java:74)
	at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193)
	at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1626)
	at org.apache.druid.server.security.AnonymousAuthenticator$1.doFilter(AnonymousAuthenticator.java:101)
	at org.apache.druid.server.security.AuthenticationWrappingFilter.doFilter(AuthenticationWrappingFilter.java:59)
	at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193)
	at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1626)
	at org.apache.druid.security.basic.authentication.BasicHTTPAuthenticator$BasicHTTPAuthenticationFilter.doFilter(BasicHTTPAuthenticator.java:172)
	at org.apache.druid.server.security.AuthenticationWrappingFilter.doFilter(AuthenticationWrappingFilter.java:59)
	at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193)
	at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1626)
	at org.apache.druid.server.security.SecuritySanityCheckFilter.doFilter(SecuritySanityCheckFilter.java:77)
	at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193)
	at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1626)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:552)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1440)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:505)
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1355)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
	at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:772)
	at org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:59)
	at org.eclipse.jetty.server.handler.StatisticsHandler.handle(StatisticsHandler.java:181)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
	at org.eclipse.jetty.server.Server.handle(Server.java:516)
	at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:487)
	at org.eclipse.jetty.server.HttpChannel$$Lambda$1183/558742581.dispatch(Unknown Source)
	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:732)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:479)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277)
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
	at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034)
	at java.lang.Thread.run(Thread.java:750)

The text was updated successfully, but these errors were encountered:

Zeyu-Chen-SFDC · 2024-09-26T01:03:49Z

Here is the flamegraph from periodic jstack captures of the broker query thread:

abhishekagarwal87 · 2024-09-26T03:41:01Z

did this query override the timeout by any chance?

Zeyu-Chen-SFDC · 2024-09-26T04:19:22Z

did this query override the timeout by any chance?

As far as I could ascertain, no. I examined the corresponding SqlQueryPlus.queryContext object in the heap and did not find any timeout override.

Zeyu-Chen-SFDC · 2024-09-26T04:54:40Z

QueryRunner and QueryScheduler objects from the heap dump:

LakshSingla · 2024-09-26T05:01:04Z

@Zeyu-Chen-SFDC Thanks for the detailed report!
Does this issue begin to happen when the broker is serving a lot of queries, and there are some that are timing out? Also, can you search for the query ID in the logs of the broker and the historical serving the queries and please share if there's something relevant.

Zeyu-Chen-SFDC · 2024-09-26T05:33:43Z

Does this issue begin to happen when the broker is serving a lot of queries, and there are some that are timing out?

We haven't seen that. All these episodes began when the broker was lightly loaded, serving at most 1 other "normal" query concurrently. And the "normal" queries completed successfully. The impact of the stuck joins is as if they simply reduced the jetty threadpool capacity by a constant.

search for the query ID in the logs of the broker and the historical serving the queries and please share if there's something relevant.

The pattern of activities from the logs is as follows:

in 300ms, our historicals finish all the subqueries successfully
then the broker allocates a buffer on the jetty thread:

INFO [sql[26da5c75-0f2e-4cbc-a521-34de6ec17638]] org.apache.druid.offheap.OffheapBufferGenerator - Allocating new intermediate processing buffer[4] of size[524,288,000]

no more broker/historicals logs, and 15min later, our router error out on the query:

org.apache.druid.server.log.LoggingRequestLogger - 2024-09-20T00:13:47.028Z	127.0.0.1		{"success":false,"exception":"Total timeout 900000 ms elapsed"}	{"query":"SELECT ....

org.apache.druid.server.AsyncQueryForwardingServlet - Exception handling request: {exceptionType=java.util.concurrent.TimeoutException, exceptionMessage=Total timeout 900000 ms elapsed, class=org.apache.druid.server.AsyncQueryForwardingServlet, exception=java.util.concurrent.TimeoutException: Total timeout 900000 ms elapsed, sqlQuery=SqlQuery{query='SELECT distinct  ...

org.apache.druid.server.log.LoggingRequestLogger - 2024-09-20T00:13:47.029Z	127.0.0.1		{"query/time":900001,"success":false}	{"query":"SELECT distinct ...

no more logs associated with the queryid are seen beyond this point

kgyrtkirk · 2024-10-04T08:05:37Z

I think #17099 should have fixed this issue
Please reopen if that's not right

abhishekagarwal87 · 2024-10-04T08:31:17Z

No. This issue can still happen as it's on the broker while #17099 fixes it on historicals. The problem being fixed in 17099 was that thread doesn't stop even after being interrupted. Problem here is that the broker HTTP thread is not being interrupted at all because the SQL HTTP thread is continuously busy in the PostJoinCursor

Zeyu-Chen-SFDC added the Uncategorized problem report label Sep 26, 2024

asdf2014 added Area - Querying and removed Uncategorized problem report labels Oct 1, 2024

kgyrtkirk closed this as completed Oct 4, 2024

abhishekagarwal87 reopened this Oct 4, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Join query on broker becomes uncancellable #17163

Join query on broker becomes uncancellable #17163

Zeyu-Chen-SFDC commented Sep 26, 2024

Zeyu-Chen-SFDC commented Sep 26, 2024

abhishekagarwal87 commented Sep 26, 2024

Zeyu-Chen-SFDC commented Sep 26, 2024

Zeyu-Chen-SFDC commented Sep 26, 2024

LakshSingla commented Sep 26, 2024

Zeyu-Chen-SFDC commented Sep 26, 2024 •

edited

Loading

kgyrtkirk commented Oct 4, 2024

abhishekagarwal87 commented Oct 4, 2024

Join query on broker becomes uncancellable #17163

Join query on broker becomes uncancellable #17163

Comments

Zeyu-Chen-SFDC commented Sep 26, 2024

Affected Version

Description

Zeyu-Chen-SFDC commented Sep 26, 2024

abhishekagarwal87 commented Sep 26, 2024

Zeyu-Chen-SFDC commented Sep 26, 2024

Zeyu-Chen-SFDC commented Sep 26, 2024

LakshSingla commented Sep 26, 2024

Zeyu-Chen-SFDC commented Sep 26, 2024 • edited Loading

kgyrtkirk commented Oct 4, 2024

abhishekagarwal87 commented Oct 4, 2024

Zeyu-Chen-SFDC commented Sep 26, 2024 •

edited

Loading