Hello All, We are seeing a weird performance issue...
# general
a
Hello All, We are seeing a weird performance issue with Druid. Sometimes queries take a long time to complete even though they return 0 or minimal rows. Below is an example of the metrics from the broker of one such query which returns 0 results. The query went to 2 historicals. query timestamp: 193058.873 Log timestamp Metric Value 193058.883 query/node/ttfb 4, 4 193058.883 query/node/time 4, 5 193058.883 query/node/bytes 6, 6 193227.321 query/cpu/time 4433 193227.321 query/time 88447 193227.321 sqlQuery/time 88462 193227.321 sqlQuery/bytes 0 193227.321 sqlQuery/planningTimeMs 13 There were 40 queries submitted in the minute 19:30 - 19:31. Out of them 27 completed within the same minute, 1 completed b/w 1931 1932. 10 b/w 1932 1933 and 1 each in the next 2 minutes. All 10 queries that completed b/w 1932 1933 took ~89 seconds to complete. Though I haven't checked the other queries, it seems too much of a coincidence that all of them took around the same time. We pulled the CPU & Memory utilization of all the hosts during this time and there wasn't much load on them. The brokers CPU utilization was <15% and memory was ~15%. The historicals CPU utilization was ~45% and memory ~20%. The same query when executed after some time completed in 0.14 seconds. We are puzzled as to why there was such a delay in the broker returning the query results originally. Does anyone have any thoughts on what might have caused the delay? We are wondering where the issue is as this issue is impacting the end users and we don't have an explanation for it. Druid Version: 27.0.0 Druid Cluster setup: 2 routers + brokers & 4 Historicals + MMs All running on Cloud VMs Brokers/Routers with 7 cores & 64 GB RAM Historicals/MMs with 16 cores & 128 GB RAM Thanks, AR.
j
Some things to check: • check native query interval to make sure it isn't querying all time. Some expression-based time filters don't allow for segment pruning • How many segments is the query scanning? What are the segment scan times? • Check filters on your query for optimal structure and placement. There are a handful of rules you can follow to ensure you are scanning the segments efficiently. If you post your query we can look for other performance tuning options. Thanks. John
a
Hi John, The query interval was for 7 segments (daily granularity) but as I mentioned, the query returns 0 results. In all our tests, the query hasn't taken >0.25 seconds except for that one time. Query: SELECT __time, sum(col 1), sum(col 2), sum(col 3) where __time between time_parse('', '') and time_parse('', '') and userId = '' There are no records for the particular user for the specified time interval so there is nothing to aggregate. Also, from the broker metrics (query/node/time & query/node/bytes), it looks like the broker received all the data from the historicals in a few milliseconds but it just didn't forward the result to the client. We haven't enabled metrics on historicals as it fills up the log file but will enable them going forward. Somehow, I don't think historicals were the cause of the delay in this case. Thanks, AR.
j
The segments still need to be scanned even if no rows are returned ... and depending on the order of the filters it could do substantial work before determining that there were no rows to return. But since you said the subquery time is fast, then it looks like that is not the issue. One other thing I can think of right now -- If this is a group by query then it needs a merge buffer, and if your numMergeBuffers value is low and other group by queries are running, this could queue up ... check the metric mergeBuffer/pendingRequests on the Broker to see if you are getting queue there.
a
Hi John, Merge buffer unavailability was my first suspicion too. The metric
mergeBuffer/pendingRequests
is not available on the version that we are running (v27.0.0). Instead, I looked at the number of requests that were submitted around that time and how long they took to complete. As I mentioned in my original post, there were 40 queries submitted in the minute 19:30 - 19:31. Out of them 27 completed within the same minute, 1 completed b/w 1931 1932. 10 b/w 1932 1933 and 1 each in the next 2 minutes. All 10 queries that completed b/w 1932 1933 took ~89 seconds to complete. We have 2 brokers with 18 merge buffers configured on each one (15 on each historical). So if 27 requests were completed in the same minute, it should have freed up enough buffers to merge the remaining 13 as soon as the results were available. Not sure why it took >80 sec for it to merge the results for the 10 requests. Is there any other metric that can provide additional details to debug this issue? For now and due to a lack of any other reason, we are planning to increase the number of merge buffers on both the historicals & brokers. Thanks, AR.