Page MenuHomePhabricator

Dropping data from druid takes down aqs hosts - part 2
Closed, ResolvedPublic

Description

In T226035 it was investigated why Druid public's broker lock up when a mw snapshot/datasource is dropped. The task was closed since we thought we had a solution, but the issue re-appeared.

We had another occurrence of AQS alarms related to the edit API failing while 2 druid datasources were cleaned up (drop issued by our systemd timer).

After a chat with Joseph and some digging into logs, we found the following:

  • All the broker timeouts seem to be related to historicals locking up for the mediawiki_reduced datasource configured in AQS (so the last one), that it is of course not the one getting dropped.
  • The coordinator leader tries to re-shuffle data around the cluster (5 segments at the time maximum), causing segments to be loaded/dropped by historicals. In this case, segments for mediawiki_reduced_2020_11 (the last datasource indexed) were moved to different hosts right after the drop of the old datasources.
  • We have segments replicated 2 times (default_tier's default) and the avg load across the public cluster is 25% (segment-cache space used on every node). We could try to increase the replication to 3 times, but we might incur into the same issue described above. It would make the cluster more resilient afterwards.

We tried to do the following:

  1. Limit the datasource drop to one datasource only if possible. In theory it should be like this, but I found logs in the coordinator telling me that mediawiki_reduced_2020_06 and `mediawiki_reduced_2020_07 were dropped at the same time.
  2. Increase replication for segments to 3.
  3. Figure out a way to limit the data shuffling caused by the coordinator.

Then we started wondering if the cache settings were at fault, since the issue seems happening when the Brokers' cache is full. More info in the task.

Event Timeline

elukey triaged this task as High priority.

Thanks for raising this. It seems to be something other folks are dealing with, if not exactly due to shuffling segments at least in a related way with a large performance variance between nodes and problems in Druid's algorithms for re-balancing queries. This is one example but there are a few active threads I found quickly: https://leventov.medium.com/the-problems-with-druid-at-large-scale-and-high-load-part-1-714d475e84c9

I followed up to my own thread (sent a looong time ago) to druid's user@ mailing list, let's see if anybody comes back with some suggestion..

Ottomata lowered the priority of this task from High to Medium.Feb 8 2021, 4:48 PM

Today it rehappened, and I noticed from the following that the broker timeouts are all related to one historical:

elukey@cumin1001:~$ sudo cumin 'A:druid-public' 'grep "ERROR org.apache.druid.server.QueryResource: Exception handling request" /var/log/druid/broker.log | grep 2021-02-12 | egrep -o "url\[http://druid100[1-9]*.eqiad.wmnet:8083" | sort | uniq -c'
5 hosts will be targeted:
druid[1004-1008].eqiad.wmnet
Confirm to continue [y/n]? y
===== NODE GROUP =====                                                                                            
(1) druid1008.eqiad.wmnet                                                                                         
----- OUTPUT of 'grep "ERROR org....| sort | uniq -c' -----                                                       
     16 url[http://druid1004.eqiad.wmnet:8083                                                                     
===== NODE GROUP =====                                                                                            
(2) druid[1004,1007].eqiad.wmnet                                                                                  
----- OUTPUT of 'grep "ERROR org....| sort | uniq -c' -----                                                       
      6 url[http://druid1004.eqiad.wmnet:8083                                                                     
===== NODE GROUP =====                                                                                            
(1) druid1006.eqiad.wmnet                                                                                         
----- OUTPUT of 'grep "ERROR org....| sort | uniq -c' -----                                                       
     22 url[http://druid1004.eqiad.wmnet:8083                                                                     
===== NODE GROUP =====                                                                                            
(1) druid1005.eqiad.wmnet                                                                                         
----- OUTPUT of 'grep "ERROR org....| sort | uniq -c' -----                                                       
     24 url[http://druid1004.eqiad.wmnet:8083

Change 663800 had a related patch set uploaded (by Elukey; owner: Elukey):
[operations/puppet@production] druid: tune Broker settings for the Public cluster

https://gerrit.wikimedia.org/r/663800

Change 663800 merged by Elukey:
[operations/puppet@production] druid: tune Broker settings for the Public cluster

https://gerrit.wikimedia.org/r/663800

After checking again a ton of docs, I tried new settings for the brokers, let's see if they work. I also followed up in the user@druid mailing list but so far no real solution has been proposed :(

Change 666597 had a related patch set uploaded (by Elukey; owner: Elukey):
[operations/puppet@production] druid: set caffeine as default cache for the Brokers

https://gerrit.wikimedia.org/r/666597

Change 666598 had a related patch set uploaded (by Elukey; owner: Elukey):
[operations/puppet@production] role::druid::public::worker: tune cache settings

https://gerrit.wikimedia.org/r/666598

Change 666597 merged by Elukey:
[operations/puppet@production] druid: set caffeine as default cache for the Brokers

https://gerrit.wikimedia.org/r/666597

Today I was stopping/starting druid daemons (one node at the time) to roll out the fixed uid/gid (unrelated task). After stopping the first historical, AQS alarmed, same issue as it happens when we drop a datasource - all brokers locked. I had to roll restart all brokers to get some recovery (during this timeframe even Wikistats 2 was impaired).

As test, I kept going with the maintenance to see if the issue was a one off or consistent, and with my great surprise it didn't rehappen (namely I was able to stop/start all the other historicals without impact). One big thing that changed between the first and the other is the cache on the broker, that it was full right before the first historical stop/start, but completely wiped afterwards. After reading https://druid.apache.org/docs/latest/querying/caching.html#query-caching-on-brokers I came up with two changes:

  • https://gerrit.wikimedia.org/r/666597 - use caffeine (see the above link) instead of local (basically JVM on-heap cache) that we had in puppet. The local caching is deprecated since 0.12.3 and discouraged.
  • https://gerrit.wikimedia.org/r/666598 - disable segment cache on brokers, enable only query caching and enable segment caching on historicals. With the current config the historicals cannot merge any segment before returning data to the broker, and with 5+ nodes (like in our use case) it is discouraged. I also think that the mw history snapshot is also super big in size/segments, playing a role.

How can the cache cause this trouble? Not entirely sure, but I suspect that there may be some slowdown on the broker when historicals change, and the cache is full.

I turned on caffeine on all brokers (on both cluster), and will leave the config running for a day. Tomorrow I'll rollout the other change if nobody opposes (only to the public cluster).

Change 666837 had a related patch set uploaded (by Elukey; owner: Elukey):
[operations/puppet@production] druid: add more cache metrics to the prometheus exporter

https://gerrit.wikimedia.org/r/666837

Change 666837 merged by Elukey:
[operations/puppet@production] druid: add more cache metrics to the prometheus exporter

https://gerrit.wikimedia.org/r/666837

Change 667558 had a related patch set uploaded (by Elukey; owner: Elukey):
[operations/puppet@production] role::druid::analytics::worker: tune cache settings

https://gerrit.wikimedia.org/r/667558

Change 667558 merged by Elukey:
[operations/puppet@production] role::druid::analytics::worker: tune cache settings

https://gerrit.wikimedia.org/r/667558

Change 666598 merged by Elukey:
[operations/puppet@production] role::druid::public::worker: tune cache settings

https://gerrit.wikimedia.org/r/666598

elukey renamed this task from Druid datasource drop triggers segment reshuffling by the coordinator to Dropping data from druid takes down aqs hosts - part 2.Mar 2 2021, 3:29 PM
elukey updated the task description. (Show Details)

We have deployed a new cache config in both clusters, with the hope that the new scheme will help when dropping data.

High level details:

  • segment caching disabled on Brokers, enabled only query-level caching
  • segment caching enabled on Historicals

Metrics looks good, now Druid Historicals are able to pre-process/merge/etc.. segments before returning them to the Brokers, that should only try to cache query results.

elukey added a project: Analytics-Kanban.
elukey moved this task from Next Up to In Progress on the Analytics-Kanban board.

Forced a data drop on Druid public and nothing really happened, the problem seems gone!

I'm adding celebration tokens to every task that I think should be celebrated. As in, if we were all in the same place I'd bake you a cake, which would take like ~2 hours, so we should take that amount of time to do something fun.