Heavy GC activities after upgrading to 0.12

[gaodayue]

After upgrading some of our historical nodes from 0.11.0 to 0.12, we observed significant performance degradation on these nodes. Below is a graph showing 99% query latency of one node. Before upgrade, it's around 100ms. After upgrade (around 16:30), it soars to almost 10s.

In addition to latency, GC activities also increased significantly.

GC log shows frequent and long STW pauses, which could be the direct cause of the increase in latency.

2018-08-27T16:34:00.400+0800: 325.630: Total time for which application threads were stopped: 3.1070312 seconds, Stopping threads took: 0.0009851 seconds
2018-08-27T16:34:03.996+0800: 329.226: Total time for which application threads were stopped: 2.8285654 seconds, Stopping threads took: 0.0032638 seconds
2018-08-27T16:34:12.182+0800: 337.412: Total time for which application threads were stopped: 1.2309673 seconds, Stopping threads took: 0.0014758 seconds
2018-08-27T16:34:16.974+0800: 342.204: Total time for which application threads were stopped: 2.2249500 seconds, Stopping threads took: 0.0005618 seconds

[gaodayue]

In order to find out which class puts too much pressure on garbage collector, I captured flight record (60s) before and after upgrade and compare them. In our cluster, each node is constantly serving ~30 queries per second, so the workload should be the same before and after.

Here are the clues I found from the record.

First, TLAB and non-TLAB allocation rate are 64MB/s and 284KB/s before upgrade, but 107MB/s and 100MB/s after upgrade. That is, non-TLAB allocated memory is 362 times more.

Second, nearly 99% of the memory is allocated from RowBasedKeySerde's constructor. It's initializing forward and reverse dictionary.

From the code we can see, the initial dictionary capacity is 10000. So every SpillGrouper needs to allocate at least two 10000-sized dictionary. We have processing.numThreads set to 31 and QPS around 30, therefore each second we're creating 1860's 10000-sized dictionary, which causes high GC activities.

Most of our groupby queries returns just a few rows, initializing 10000-sized dictionary is a waste.

This bug was introduced by #4707. Before 0.12, initial dictionary is empty. #4707 changes it to 10000.

[gianm]

Great catch!

Btw, I think you meant to link to #4704 instead of #4707.

[himanshug]

#4704 did run the benchmarks for performance, unfortunately benchmarks don't report memory allocation or else it would be noticed while #4704 was under development. it would be nice if benchmarks could report some stats on memory as well.

[jihoonson]

@gaodayue thank you for catching this. Could you share some more details of your use case? I wonder especially how large the dictionary was. I set the initial size of dictionary map to 10000 because I thought SpillingGrouper isn't supposed to be used for small dictionary.

[jihoonson]

@gaodayue I've approved #6256, but I'm still curious about my question. It would help to decide the more proper initial size of dictionary.

[gaodayue]

@gaodayue thank you for catching this. Could you share some more details of your use case? I wonder especially how large the dictionary was. I set the initial size of dictionary map to 10000 because I thought SpillingGrouper isn't supposed to be used for small dictionary.

Hi @jihoonson , as you commented in #6256 , ConcurrentGrouper always uses SpillingGrouper as sub-groupers no matter whether spilling is enabled or not. So dictionary is initialized for all groupby queries even when it's not used (not grouping by string columns).

One of our use cases is providing realtime KPI monitoring for BD (business developer). The query for each BD is something like where bd=xx and dim1=yy group by bd, dim1. As a result, the size of dictionary used in merging is always 2.

[gaodayue]

As I mentioned above, the creation rate of merging dictionary is roughly 2 (forward and reverse dict) x processing.numThreads (ConcurrentGrouper's concurrency) x QPS. The higher processing.numThreads and qps, the greater the probability to encounter the problem.

[jihoonson]

@gaodayue thank you for the details! Probably we can optimize the initial dictionary size based on 1) spilling is enabled, 2) the column is dictionary encoded, 3) the cardinality of the column, and 4) the filter selectivity.

[somanullah]

Is there a workaround for this issue?

[gianm]

Hi @somanullah, no, although a fix is included in 0.12.3, which you can get a release candidate of here: http://druid.io/downloads. If you have a chance to try that out, please let us know!