Join query on broker becomes uncancellable

[Zeyu-Chen-SFDC]

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)

[Zeyu-Chen-SFDC]

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

[abhishekagarwal87]

did this query override the timeout by any chance?

[Zeyu-Chen-SFDC]

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]

QueryRunner and QueryScheduler objects from the heap dump:

[LakshSingla]

@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]

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