https://linen.dev logo
Join Slack
Powered by
This message was deleted.
# troubleshooting
s
This message was deleted.
d
When we had our major outage, likely due to 
LIKE
queries. I random sampled N Historical pods and run jstack on them. All of the processing threads are stuck and they all stuck the same way. Either a groupBy:
Copy code
"groupBy_JoinDataSource{left=problematic-table, right=InlineDataSource{signature={__time:LONG, d0:STRING, a0:LONG}}, rightPrefix='j0.', condition=(substring("problematic_column", 0, 3) == "j0.d0"), joinType=INNER, leftFilter=null}_[2022-09-26T00:00:00.000Z/2022-09-27T00:00:00.000Z]" #502 daemon prio=5 os_prio=0 cpu=684108891.95ms elapsed=1966818.51s tid=0x00007f17a0115c60 nid=612 runnable  [0x00007e9b2e327000]
   java.lang.Thread.State: RUNNABLE
    at java.lang.StringLatin1.regionMatchesCI(java.base@18.0.2.1/StringLatin1.java:394)
    at java.lang.String.regionMatches(java.base@18.0.2.1/String.java:2226)
    at java.lang.String.equalsIgnoreCase(java.base@18.0.2.1/String.java:1962)
    at java.lang.Boolean.parseBoolean(java.base@18.0.2.1/Boolean.java:149)
    at org.apache.druid.math.expr.Evals.asBoolean(Evals.java:72)
    at org.apache.druid.math.expr.ExprEval$StringExprEval.asBoolean(ExprEval.java:932)
    at org.apache.druid.segment.filter.ExpressionFilter$2.matches(ExpressionFilter.java:208)
    at org.apache.druid.segment.filter.NotFilter$1.matches(NotFilter.java:71)
    at org.apache.druid.segment.filter.AndFilter$1.matches(AndFilter.java:205)
    at org.apache.druid.segment.join.PostJoinCursor.advanceToMatch(PostJoinCursor.java:71)
    at org.apache.druid.segment.join.PostJoinCursor.advanceUninterruptibly(PostJoinCursor.java:100)
    at org.apache.druid.segment.join.PostJoinCursor.advance(PostJoinCursor.java:92)
or a topN:
Copy code
"topN_problematic-table_[2022-06-18T00:00:00.000Z/2022-06-19T00:00:00.000Z]" #505 daemon prio=5 os_prio=0 cpu=24162945.76ms elapsed=1966818.48s tid=0x00007f17a008c420 nid=615 runnable  [0x00007e9b2e023000]
   java.lang.Thread.State: RUNNABLE
   at java.util.HashMap.getNode(java.base@18.0.2.1/HashMap.java:577)
   at java.util.HashMap.get(java.base@18.0.2.1/HashMap.java:556)
   at org.apache.druid.math.expr.InputBindings$6.get(InputBindings.java:144)
   at org.apache.druid.math.expr.IdentifierExpr.eval(IdentifierExpr.java:131)
   at org.apache.druid.math.expr.BinaryBooleanOpExprBase.eval(BinaryOperatorExpr.java:173)
   at org.apache.druid.math.expr.BinOrExpr.eval(BinaryLogicalOperatorExpr.java:399)
   at org.apache.druid.math.expr.BinOrExpr.eval(BinaryLogicalOperatorExpr.java:397)
   at org.apache.druid.math.expr.BinOrExpr.eval(BinaryLogicalOperatorExpr.java:397)
Also, I saw about 7-8 GC threads running with high CPU time at the bottom of jstack. Not sure if that information is useful or not.
So first question, is there a way to know what the topN is actually doing? I cannot tell which Boolean operation it does.
Second question, are the threads supposed to have such high cpu time? That number doesn’t look right. Does druid reap the processing thread after it is done working?
Third question is related to my previous question. It doesn’t look like Historical clean its own processing threads even when Broker already timed out the query. In theory if there are no bugs, even if there’s a brutal 
LIKE
query running, our 5 minutes Broker timeout should have killed the query and the query should have been killed at Historical level as well, right?
The easiest way to replicate this behavior is by using Druid’s full text search on a huge table. You will see that all of Historical processing threads would hang.
This happened on JVM 18 G1 GC, which already have superior performance compared to older G1 GC versions.
the time range of our 
LIKE
queries are usually between 1 month to 1 quarter.
Inside 
DruidProcessingModule
, I don’t see that 
PrioritizedExecutorService
inside 
getProcessingExecutorPool
can be configured to be cancellable after X timeout.
Should 
PrioritizedExecutorService
implement 
invokeAll
so that any 
Runnable
task can be killed after X timeout (and then have a global setting for timeout)?
I see the 
awaitTermination
method, but I don’t see where is it being called. But anyway, it looks like that’s for shutting down the entire pool.
I see that this is how the pool is actually being used: 
queryProcessingPool.submitRunnerTask
I see, it relied on 
QueryTimeoutException
to stop. and one way to set the timeout is via the context:
Copy code
QueryContexts.hasTimeout(query) ?
                      future.get(QueryContexts.getTimeout(query), TimeUnit.MILLISECONDS) :
                      future.get()
Then… this begs a question, if the Historical JVM is too busy collecting so much garbage (i.e. when it loads so many rows), will 
QueryTimeoutException
actually be raised?
l
Regarding the question:
So first question, is there a way to know what the topN is actually doing? I cannot tell which Boolean operation it does.
Can you please share the topN query that is being run please. Also, I am not super familiar with jstack, however for the topN’s trace, should there be more lines (tracing back to Thread.run())?
d
it’s a bit hard to find the exact topN query that matches the trace in jstack.
g
hard to say exactly what's going on here from the thread dumps, but it doesn't seem to me to be LIKE related
the first dump you posted is some kind of expression filter after a join. could be anything; definitely seeing the query itself would be helpful
do you have request logging enabled? you might be able to find it that way https://druid.apache.org/docs/latest/operations/request-logging.html
a little pitch for Imply 😉 one of our products, Clarity, is all about gathering these kind of details. the workflow there is: 1) we show you all the query IDs you ran, sorted by total amount of CPU time used 2) use this to track down the query IDs that used the most CPU time during the problematic time frame 3) check your request logs for those specific query IDs; take some action
the second thread dump, btw, is also an expression of some sort; again unfortunately hard to tell what it is or where it's getting called in the topN logic. some more of the stack trace would illuminate where it's getting called in the topN logic, but likely won't tell us what the expression actually is
Open in Slack
PreviousNext
Powered by