https://linen.dev logo
Join Slack
Powered by
This message was deleted.
# troubleshooting
s
This message was deleted.
d
More troubling is that many of our Superset queries are failing quickly with the following message:
Copy code
Error: Plan validation failed (org.apache.calcite.tools.ValidationException): org.apache.calcite.runtime.CalciteContextException: From line 6, column 7 to line 6, column 14: Column '__time' not found in any table
This is on Druid 0.23.0
The full error:
Copy code
druid-broker-12 druid-broker 2023-01-05T16:11:29,121 ERROR [DruidSchema-Cache-0] org.apache.druid.query.ResultLevelCachingQueryRunner - Error while preparing for result level caching for query e73d2ca2-c8f9-409b-8e31-b8469713b1ab with error Sequence iterator timed out waiting for data 
druid-broker-12 druid-broker org.apache.druid.query.QueryTimeoutException: Sequence iterator timed out waiting for data
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.ParallelMergeCombiningSequence$1$1.hasNext(ParallelMergeCombiningSequence.java:205) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.BaseSequence.makeYielder(BaseSequence.java:89) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.BaseSequence.toYielder(BaseSequence.java:69) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.WrappingSequence$2.get(WrappingSequence.java:88) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.WrappingSequence$2.get(WrappingSequence.java:84) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.SequenceWrapper.wrap(SequenceWrapper.java:55) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.WrappingSequence.toYielder(WrappingSequence.java:83) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.ParallelMergeCombiningSequence.toYielder(ParallelMergeCombiningSequence.java:153) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.LazySequence.toYielder(LazySequence.java:46) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.WrappingSequence$2.get(WrappingSequence.java:88) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.WrappingSequence$2.get(WrappingSequence.java:84) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.SequenceWrapper.wrap(SequenceWrapper.java:55) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.WrappingSequence.toYielder(WrappingSequence.java:83) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.MergeSequence.lambda$toYielder$1(MergeSequence.java:66) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.BaseSequence.accumulate(BaseSequence.java:44) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.MergeSequence.toYielder(MergeSequence.java:63) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.query.RetryQueryRunner$1.toYielder(RetryQueryRunner.java:133) ~[druid-server-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.common.guava.CombiningSequence.toYielder(CombiningSequence.java:78) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.MappedSequence.toYielder(MappedSequence.java:49) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.MappedSequence.toYielder(MappedSequence.java:49) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.WrappingSequence$2.get(WrappingSequence.java:88) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.WrappingSequence$2.get(WrappingSequence.java:84) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.query.CPUTimeMetricQueryRunner$1.wrap(CPUTimeMetricQueryRunner.java:77) ~[druid-processing-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.WrappingSequence.toYielder(WrappingSequence.java:83) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.MappedSequence.toYielder(MappedSequence.java:49) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.WrappingSequence$2.get(WrappingSequence.java:88) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.WrappingSequence$2.get(WrappingSequence.java:84) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.SequenceWrapper.wrap(SequenceWrapper.java:55) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.WrappingSequence.toYielder(WrappingSequence.java:83) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.WrappingSequence$2.get(WrappingSequence.java:88) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.WrappingSequence$2.get(WrappingSequence.java:84) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.SequenceWrapper.wrap(SequenceWrapper.java:55) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.WrappingSequence.toYielder(WrappingSequence.java:83) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.java.util.common.guava.Yielders.each(Yielders.java:32) ~[druid-core-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.sql.calcite.schema.DruidSchema.refreshSegmentsForDataSource(DruidSchema.java:705) ~[druid-sql-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.sql.calcite.schema.DruidSchema.refreshSegments(DruidSchema.java:658) ~[druid-sql-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.sql.calcite.schema.DruidSchema.refresh(DruidSchema.java:390) ~[druid-sql-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at org.apache.druid.sql.calcite.schema.DruidSchema.lambda$startCacheExec$1(DruidSchema.java:337) ~[druid-sql-0.23.0.jar:0.23.0]
druid-broker-12 druid-broker 	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) [?:?]
druid-broker-12 druid-broker 	at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
druid-broker-12 druid-broker 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
druid-broker-12 druid-broker 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
druid-broker-12 druid-broker 	at java.lang.Thread.run(Thread.java:833) [?:?]
druid-broker-12 druid-broker 	Suppressed: java.lang.NullPointerException
This is fascinating:
Copy code
Suppressed: java.lang.NullPointerException
t
@Didip Kerabat - Do you have query logging turned on to see what types are queries are causing the timeout? Also, if you re-run the query (or queries) in question causing the errors do you get a consistent timeout?
d
we do have a real time list of all the queries. When we re-run the queries, some completed and some timed out again. So far I am not seeing any patterns (e.g. a bad full text search).
t
@Didip Kerabat - Also can you check to see if there are any other errors or warnings in the master logs or broker logs around when the query timeout occured?
d
so, we just finished rolling restart the brokers now. And things looked a lot better. It looks like a lot of broker threads (in the thread pool) failed silently and they are not being refreshed/reaped properly. This kind of explained why our cluster were not busy even though there were a lot of errors. The queries failed at broker level before they even made it to Historicals.
too bad for our uptime tho 🙂 the cluster were doing quite well for 77 days.
t
@Didip Kerabat - Yes 🥲 for the uptime. A few questions... Have you see this issue re-occur in the past? I ask because looking around on my side seems to indicate a restart of the broker clear the issue, but it eventually returns.
d
This is actually the first time we saw this issue.
đź‘Ť 1
b
I've come across this some lately, also saw restarting brokers cleared it for a while. Iirc, the issues I saw were related to lookups, and tuning things like druid.manager.lookups.threadPoolSize on the coordinator and druid.lookup.numLookupLoadingThreads on places lookups were loading helped. Not sure if that applies in your case.
d
Interesting. We banned to use of lookups, but lookup is still turned on in our config. I’ll take a look at it.
b
If you don't have any lookups, then pretty sure that's not the issue here.
v
You have results level caching turned on in the broker?
If you use result level cache and use cache true in the broker then the load on the broker will be large. Use cache will cache segment level results on the broker and all the merging will happen on the broker. This will overload the broker. I suggest turning off all caching on the broker and setting use cache and populate cache to true in the historicals
d
We do have result level caching turned on in the broker. interesting… the cache is not large, only 5GB on each broker. Is it best to just turn off cache completely in broker?
v
yes. The cache is store on heap. What is the Xmx on your broker. Result level cache is useful only if you have the same queries and data again and again.
d
xmx is fairly generous: 24GB this is on G1 GC
The broker cache hit rate is actually pretty good: 98%
v
ok. If useCache and populateCache is also true on broker then the broker will definitely get overloaded. I would set both useCache and useResultLevelCache to false on the broker
d
ah, useCache and populateCache are definitely false. Those two settings don’t work on large clusters. In the past we had an outage because those two were on.
v
How many vcpu do you have on the broker?
d
We only gave it 5 CPU in Kubernetes because on normal situations, it barely used 3 CPUs.
v
hmm…what kind of queries do you have and what concurrency?
d
and there are 38 brokers total
on average number of queries aren’t a lot. 20k-40k per day. These came from Superset dashboards.
v
the sequence iterator error is a basically a timeout.
this could be also due to the amount of data the queries are scanning or a lot of data being returned to broker for merging.
d
yeah, I think there’s an underlying issue that got masked. See:
Copy code
Suppressed: java.lang.NullPointerException
Some threads basically didn’t do anything until the 5 minutes timeout kicked in.
v
what type of query is this?
Are you doing a union query?
d
and that explained why on our datadog, historicals looked so free as if they are not doing anything.
There are no patterns in the failed queries. Some do groupBy, some do topN, some do nested SELECT queries, some do full text search like “abc123%“, etc.
v
how many historicals do you have?
d
512, each with 11 CPUs
v
ok..with this many historicals the merge load on the broker for groupbys will be very large.
I would look at using 50 historicals with 110 vcpu each and around 5 brokers with 35 vcpu each.
d
the problem with assigning a lot of CPU is that the processing thread is expensive on memory, no? The merge buffer is 2gb and based on this math:
Copy code
DRUIDHISTORICAL_PROCESSING_NUMMERGEBUFFERS + DRUIDHISTORICAL_PROCESSING_NUMTHREADS + 1) * DRUIDHISTORICAL_PROCESSING_BUFFER_SIZEBYTES
that already consumed 66gb of DirectMemory size.
both 
DRUIDHISTORICAL_PROCESSING_NUMMERGEBUFFERS
and 
DRUIDHISTORICAL_PROCESSING_NUMTHREADS
are 16
v
this is true irrespectoive of how you split the historicals. You may slice it different ways but your overall processing threads should remain the same. If with 11 vcpu you are setting processing threads to 16 then you are over comitting the threads.
d
we used to set it to 16 CPU, but our average cpu usage graph showed that we almost never used > 8-9 CPUs
v
this likely means that there are bottlenecks that prevent the historicals from taking on the full load. It may be the http connections or threads and few other things.
d
interesting. jetty threads are quite generous as well: 500
v
anyway having fewer larger servers should not increase direct memory
having too many small servers is generally not a good idea.
the aggregations coming through from each historical gets merged on the broker…with 512 servers your merge will be much larger than with 50 servers. And there is only one broker for one query. So that one broker will take that full load.
d
i see, can this be mitigated with more brokers?
v
probably not as you have 38 brokers and less that 1 query per second. Very likely each broker is doing only one query at a time.
here is another thought…by default the broker does parallel combine and can use 75% of available CPU for that. In your case the max available CPU for a query on the broker is 5. So a query that could move faster with a larger broker will slow down a lot with your approach.
the simplest change you can make is have 5 brokers with 35 vcpu each. Reduce processing threads on brokers to 1 (brokers don’t need processing threads) and set numMergeBuffers =5 on each broker (so you need only (5+1+1)*2=14GB direct memeory. The 35 vcpu will allow significantly more merge threads to come into play
d
oooo that’s an interesting suggestion. Thank you. We’ll play with this on our lab.
3 Views
Open in Slack
PreviousNext
Powered by