Hi all My Druid cluster in k8s is suffering from a huge perf Apache Druid #troubleshooting

Hi all, My Druid cluster (in k8s) is suffering fr...

Lionel Mena

03/23/2023, 10:17 AM

Hi all, My Druid cluster (in k8s) is suffering from a huge performance degradation that I'm unable to find the root cause. We use Druid to power some analytics dashboards and we notice that upon loading a dashboard any other query starts timing out (no Druid time limit has been set it's our load balancer which timeouts connections after 60 seconds). The cluster enter in a degraded state, we tried running a single query that tipically take <1s and it keeps running for more than 60s. The cluster takes around and hour to perform back to normal but forcing a restart on the broker services also mitigates the issue. I've attached an screenshot of our cluster topology and I been able to collect log lines (broker) associated to the dashboard queries that trigger the issue. These queries seems to fail because of the subquery results default limitation of number of rows

Copy code

2023-03-22T17:06:40+00:00	2023-03-22T17:06:40,593 WARN [sql[a97928d9-bd83-4478-840f-9d6332a33916]] org.apache.druid.server.QueryLifecycle - Exception while processing queryId [553272ba-21ec-4655-bf43-704133b9bcbb] (org.apache.druid.query.ResourceLimitExceededException: Subquery generated results beyond maximum[100000])
2023-03-22T17:06:41+00:00	2023-03-22T17:06:41,409 WARN [sql[d8a66e60-4cee-4388-bfac-fa18edb370f5]] org.apache.druid.server.QueryLifecycle - Exception while processing queryId [6652a9f4-3980-4533-b861-7b0e37eccdc2] (org.apache.druid.query.ResourceLimitExceededException: Subquery generated results beyond maximum[100000])
2023-03-22T17:06:42+00:00	2023-03-22T17:06:42,919 WARN [sql[b344d453-54ed-4814-97f1-2711b9478c87]] org.apache.druid.server.QueryLifecycle - Exception while processing queryId [1167828c-f2fb-46e5-bdca-539e979214e3] (org.apache.druid.query.ResourceLimitExceededException: Subquery generated results beyond maximum[100000])

but then another cryptic error start appearing rigth afterwards

Copy code

2023-03-22T17:11:35+00:00	2023-03-22T17:11:35,564 WARN [ForkJoinPool-1-worker-14] org.apache.druid.java.util.common.guava.ParallelMergeCombiningSequence - Failed to close result cursors
org.apache.druid.query.QueryTimeoutException: Query[c5df16ae-12f3-45aa-8fe9-c18bed6c9ef6] url[<http://172.42.0.173:8100/druid/v2/>] timed out.
	at org.apache.druid.client.DirectDruidClient$1.checkQueryTimeout(DirectDruidClient.java:427) ~[druid-server-0.23.0.jar:0.23.0]
	at org.apache.druid.client.DirectDruidClient$1.access$500(DirectDruidClient.java:173) ~[druid-server-0.23.0.jar:0.23.0]
	at org.apache.druid.client.DirectDruidClient$1$2.hasMoreElements(DirectDruidClient.java:282) ~[druid-server-0.23.0.jar:0.23.0]
	at java.io.SequenceInputStream.nextStream(SequenceInputStream.java:109) ~[?:1.8.0_275]
	at java.io.SequenceInputStream.close(SequenceInputStream.java:232) ~[?:1.8.0_275]
	at com.fasterxml.jackson.dataformat.smile.SmileParser._closeInput(SmileParser.java:309) ~[jackson-dataformat-smile-2.10.5.jar:2.10.5]
	at com.fasterxml.jackson.dataformat.smile.SmileParserBase.close(SmileParserBase.java:384) ~[jackson-dataformat-smile-2.10.5.jar:2.10.5]
	at org.apache.druid.client.JsonParserIterator.close(JsonParserIterator.java:138) ~[druid-server-0.23.0.jar:0.23.0]
	at org.apache.druid.utils.CloseableUtils.closeAndWrapExceptions(CloseableUtils.java:139) ~[druid-core-0.23.0.jar:0.23.0]
	at org.apache.druid.client.DirectDruidClient$3.cleanup(DirectDruidClient.java:515) ~[druid-server-0.23.0.jar:0.23.0]
	at org.apache.druid.client.DirectDruidClient$3.cleanup(DirectDruidClient.java:498) ~[druid-server-0.23.0.jar:0.23.0]
	at org.apache.druid.java.util.common.guava.BaseSequence$1.close(BaseSequence.java:136) ~[druid-core-0.23.0.jar:0.23.0]
	at org.apache.druid.java.util.common.guava.ParallelMergeCombiningSequence$YielderBatchedResultsCursor.close(ParallelMergeCombiningSequence.java:1072) ~[druid-core-0.23.0.jar:0.23.0]
	at org.apache.druid.java.util.common.io.Closer.close(Closer.java:182) ~[druid-core-0.23.0.jar:0.23.0]
	at org.apache.druid.utils.CloseableUtils.closeAndSuppressExceptions(CloseableUtils.java:162) [druid-core-0.23.0.jar:0.23.0]
	at org.apache.druid.java.util.common.guava.ParallelMergeCombiningSequence.closeAllCursors(ParallelMergeCombiningSequence.java:1385) [druid-core-0.23.0.jar:0.23.0]
	at org.apache.druid.java.util.common.guava.ParallelMergeCombiningSequence.access$400(ParallelMergeCombiningSequence.java:63) [druid-core-0.23.0.jar:0.23.0]
	at org.apache.druid.java.util.common.guava.ParallelMergeCombiningSequence$MergeCombineAction.compute(ParallelMergeCombiningSequence.java:666) [druid-core-0.23.0.jar:0.23.0]
	at java.util.concurrent.RecursiveAction.exec(RecursiveAction.java:189) [?:1.8.0_275]
	at java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:289) [?:1.8.0_275]
	at java.util.concurrent.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1056) [?:1.8.0_275]
	at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1692) [?:1.8.0_275]
	at java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:175) [?:1.8.0_275]
	Suppressed: org.apache.druid.query.QueryTimeoutException: Query[c5df16ae-12f3-45aa-8fe9-c18bed6c9ef6] url[<http://172.42.0.156:8100/druid/v2/>] timed out.
		at org.apache.druid.client.DirectDruidClient$1.checkQueryTimeout(DirectDruidClient.java:427) ~[druid-server-0.23.0.jar:0.23.0]
		at org.apache.druid.client.DirectDruidClient$1.access$500(DirectDruidClient.java:173) ~[druid-server-0.23.0.jar:0.23.0]
		at org.apache.druid.client.DirectDruidClient$1$2.hasMoreElements(DirectDruidClient.java:282) ~[druid-server-0.23.0.jar:0.23.0]
		at java.io.SequenceInputStream.nextStream(SequenceInputStream.java:109) ~[?:1.8.0_275]
		at java.io.SequenceInputStream.close(SequenceInputStream.java:232) ~[?:1.8.0_275]
		at com.fasterxml.jackson.dataformat.smile.SmileParser._closeInput(SmileParser.java:309) ~[jackson-dataformat-smile-2.10.5.jar:2.10.5]
		at com.fasterxml.jackson.dataformat.smile.SmileParserBase.close(SmileParserBase.java:384) ~[jackson-dataformat-smile-2.10.5.jar:2.10.5]
		at org.apache.druid.client.JsonParserIterator.close(JsonParserIterator.java:138) ~[druid-server-0.23.0.jar:0.23.0]
		at org.apache.druid.utils.CloseableUtils.closeAndWrapExceptions(CloseableUtils.java:139) ~[druid-core-0.23.0.jar:0.23.0]
		at org.apache.druid.client.DirectDruidClient$3.cleanup(DirectDruidClient.java:515) ~[druid-server-0.23.0.jar:0.23.0]
		at org.apache.druid.client.DirectDruidClient$3.cleanup(DirectDruidClient.java:498) ~[druid-server-0.23.0.jar:0.23.0]
		at org.apache.druid.java.util.common.guava.BaseSequence$1.close(BaseSequence.java:136) ~[druid-core-0.23.0.jar:0.23.0]
		at org.apache.druid.java.util.common.guava.ParallelMergeCombiningSequence$YielderBatchedResultsCursor.close(ParallelMergeCombiningSequence.java:1072) ~[druid-core-0.23.0.jar:0.23.0]
		at org.apache.druid.java.util.common.io.Closer.close(Closer.java:182) ~[druid-core-0.23.0.jar:0.23.0]
		at org.apache.druid.utils.CloseableUtils.closeAndSuppressExceptions(CloseableUtils.java:162) [druid-core-0.23.0.jar:0.23.0]
		at org.apache.druid.java.util.common.guava.ParallelMergeCombiningSequence.closeAllCursors(ParallelMergeCombiningSequence.java:1385) [druid-core-0.23.0.jar:0.23.0]
		at org.apache.druid.java.util.common.guava.ParallelMergeCombiningSequence.access$400(ParallelMergeCombiningSequence.java:63) [druid-core-0.23.0.jar:0.23.0]
		at org.apache.druid.java.util.common.guava.ParallelMergeCombiningSequence$MergeCombineAction.compute(ParallelMergeCombiningSequence.java:666) [druid-core-0.23.0.jar:0.23.0]
		at java.util.concurrent.RecursiveAction.exec(RecursiveAction.java:189) [?:1.8.0_275]
		at java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:289) [?:1.8.0_275]
		at java.util.concurrent.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1056) [?:1.8.0_275]
		at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1692) [?:1.8.0_275]
		at java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:175) [?:1.8.0_275]

I'll also attached the configuration of the historicals and brokers. I'm running Druid

v0.23.0

I think this is a backpressure issue but my knowdlege is really limited. What do you think is the root cause of this severe performance degradation? Let me know if you need any other logs. Thanks

broker-settings.txt historical-settings.txt broker_queries_issues.txt

Vijay Narayanan

03/23/2023, 10:28 AM

Do you have a sense of cpu utilization when this issue occurs. You may just be running out of resources.

Lionel Mena

03/23/2023, 10:38 AM

Thank you for bringing that up. I saw no resource exhaustion. Historicals used no more than 1.5 CPU and broker even less, < 0.5 CPU As per RAM, it was stable on Historicals and there was a spike in brokers from 11 gb to 19 GB and a limit of 12GB per broker was set on kubernetes resource limit

Lionel Mena

03/23/2023, 10:39 AM

https://snapshots.raintank.io/dashboard/snapshot/NxLQqF2jBF1AxhTaBWC4ktFajUDg9jSi

Renato Santos

03/23/2023, 10:40 AM

Copy code

Exception while processing queryId [553272ba-21ec-4655-bf43-704133b9bcbb] (org.apache.druid.query.ResourceLimitExceededException: Subquery generated results beyond maximum[100000])

You can change this number in the config, but if this is being hit, the queires need to be rearchitected

Lionel Mena

03/23/2023, 10:41 AM

Indeed we make intensive use of subqueries and JOINs to calculate more metrics out of the reported ones ..

Renato Santos

03/23/2023, 10:43 AM

I would start searching for this query and checking if it can be rewrite to use some form of aggregation where druid can use sketch or other approximate algorithms that uses way less ram. if they can't be changed, then this would need to be saved already calculated upfront for the dashboard

Lionel Mena

03/23/2023, 10:48 AM

I understand that hitting that

rg.apache.druid.query.ResourceLimitExceededException: Subquery generated results beyond maximum[100000])

requires from reworking our queries but aside from this, what would explain the overall performance degradation? This limit is basically a guardrail to prevent from having performance issues.

Renato Santos

03/23/2023, 11:26 AM

I'm not 100% sure, but I think that broker (or router, I can't remember now) may retry the query a few times if a historicals fail, so that's why from a client (dashboard) perspective, you would see a timeout if all of the retries got the same resource error in end, and I think that, even if your LB (on k8s or amazon) has a timeout, the broker by default has not, and would keep running the query)

Renato Santos

03/23/2023, 11:27 AM

on my cluster I've set a default timeout of 60 secs for all queries, and only overwrite it on a query-by-query basis

Renato Santos

03/23/2023, 11:28 AM

druid.server.http.defaultQueryTimeout=60000

I think it must be set both on and brokers

Renato Santos

03/23/2023, 11:30 AM

the default value is 300000 (5min)

Renato Santos

03/23/2023, 11:32 AM

also, druid.broker.retryPolicy.numTries=1 so I don't think it's that is causing the cluster to be unresponsive 😕

Vijay Narayanan

03/23/2023, 11:39 AM

the broker may be a major bottleneck when subqueries are involved. Do you have a load testing script?

Vijay Narayanan

03/23/2023, 11:40 AM

can you send me some example queries?

Vijay Narayanan

03/23/2023, 11:45 AM

I was helping another customer a few months ago where union queries were causing time out issues though the historicals were not maxed out in terms of CPU

Lionel Mena

03/23/2023, 11:48 AM

I did a load testing in the past to find out about concurrency capacity but the performance never got degraded in such a way. Once the test finish its 2min execution you could isue any querie withouth any issues ... Let me fetch some queries

Lionel Mena

03/23/2023, 11:57 AM

Copy code

SELECT "t1"."timestamp", "t2"."Source", "t2"."ParentId", "t2"." "
FROM 
(
SELECT TIME_FLOOR(__time, 'PT${period}') "timestamp", NodeId, ReceiveFromNodeId
FROM "sdk-${region}-realtime"
WHERE __time >= '${__from:date:iso}' AND  __time < '${__to:date:iso}'

  AND CustomerId = '${customerid}'
  AND ChannelId LIKE '${channelid}'
  AND NodeId = '${nodeid}'
  AND ReceiveFromNodeId != ''
  AND RepresentationId LIKE '${representationid}'
  AND MaskedStreamUri LIKE '${maskedstreamuri}'

) AS "t1"
INNER JOIN
(
SELECT TIME_FLOOR(__time, 'PT${period}') as "timestamp", NodeId as "ParentId", Source, AVG(BufferHealth) / 1000.0 " "
FROM "sdk-${region}-realtime"
WHERE __time >= '${__from:date:iso}' AND  __time < '${__to:date:iso}'

  AND CustomerId = '${customerid}'
  AND ChannelId LIKE '${channelid}'
  AND RepresentationId LIKE '${representationid}'
  AND MaskedStreamUri LIKE '${maskedstreamuri}'
  
GROUP BY 1, 2, 3
) AS "t2" 
ON "t1"."timestamp" = "t2"."timestamp" AND "t1".ReceiveFromNodeId = "t2"."ParentId"

Renato Santos

03/23/2023, 2:24 PM

I think that, for now you can add more brokers to help with the joining, but you are paying the price of the join at each query, this will not scale. you can try enable caching on broker side (it's disabled by default) but that can only help if the dash send identical queries. You should do peform this join in a previous stream (eg: using any engine u like, spark, or kafka stream (can do with query using ksql) so in druid you can just consume from one topic, and even use roll-up choose different datasource depending on the time_floor you want) so your query will run in just a few ms

Lionel Mena

03/23/2023, 2:40 PM

Thanks for your suggestion @Renato Santos I'l take them into account. We were already using the scheme/layout of realtime/historical datasources with different rollups so we target one of them depending on the selected query time range/granularity. From documentation, I also had the feeling that our queries were pushing too far out of Druid so that kind of confirmed our suspicions on that regards. Lastly, didn't know that merging query partial results could be parallelized in more than on broker.

Renato Santos

03/23/2023, 2:43 PM

just one broker will be joining per query (on the classic engine), but if you have multiple queries, more brokers will help parallelize)

Lionel Mena

03/23/2023, 2:57 PM

mmm, ok

Vijay Narayanan

03/23/2023, 3:45 PM

is there any reason to use like filters rather than in filters? If the fields are string fields in filters are way faster and that might help. A lot depends on how much comes to the broker from the left and right queries of the join

Lionel Mena

03/23/2023, 3:53 PM

The queries are sent from Grafana dashboards. Each of those conditions translate to a Grafana dashboard variable so you can get a drop-down menu that let you filter by those. However those filters doesn't have static values. They are obtained (via query) dynamically. WHat if you don't whant to filter by any of those attributes? Well. Gafana allows you to customise the value to send when you don't want to filter out by any of those. Sending "%" was the only workaround we could come up with

Renato Santos

03/23/2023, 4:10 PM

yeah, I usually don't use grafana sor I dont know if there's any way to do conditional templates like is on metabase, but a hack I use is using 2 binds and doing something like this:

Copy code

AND ( CAST(? AS int) = 0 OR col IN (:cols:))

and pass a 1 for ignore the IN condition (and use a fake value in the list, calcite will remove this expression entirely as it always will be false but I wrote a custom sql placeholder where I mix in both ? and list of some values that will be replaced before sending to druid

Lionel Mena

03/23/2023, 5:02 PM

That's a nice trick, Due to our filtering values distribution we had to chose

-1

to disable the IN filter and we couldn't inject two values but it worked. Thanks @Renato Santos

Copy code

AND (CAST('${channelid}' AS int) = -1 OR ChannelId IN ('${channelid}'))

🙌 2

3 Views

Open in Slack

Previous Next