Cluster node startup takes longer than 2 hours

[motmot80]

Description

Cluster node restart takes longer than two hours without consuming system ressources.

Reproduction

1. Fillup node with setup below
2. Stop one node
3. Restart node

Rabbit MQ setup

Rabbit MQ-Version: 3.8.1 (Erlang 22.1.6)
Nodes count: 3
Node hardware: 6 CPUs - 32 GB RAM each [edited]

Expected

Node starts within a few minutes

Actual

Node start always takes longer than 120 minutes.
1h:40m without logging (debug) any progress.
Except [Re-]registered this node which seems to be something like a cluster heart beat ([empd] 25762).
See log analysis below.

Reproduction setup

Type	Count	Description
Queues (lazy)	80 000	20 000 per node
Queues (non-persistent)	20
Queues (HA)	1
Exchanges	32
Bindings	1 200 000
Messages ready	20 000 000	in lazy queues

Log analysis

Duration	Count occur.	Phase
6s	1	Started
2m:12s	1	Prelaunch
13m:12s	23300	ERROR - in an old incarnation (3) of this node (1)
1h:2m:10s	1	NO OPERATION - after WARN rabbit_sysmon_handler busy_dist_port
4s	1	Supervisor started
1m:24s	1	Started message store
7s	1	Rebuilding message location index started
<1s	1	Rebuilding message location index finished
<1s	1	Started message store of type persistent
7s	20 000 [edited]	start_links LAZY-QUEUES
41m:16s	1	NO OPERATION - after WARN lager_error_logger_h dropped 646 messages
1s	1	start_link HA-QUEUE
1s	1	Application started..
<1s	1	Plugins starting
7s	1	Finished

System load during startup

CPU: < 25 %
RAM: < 15 %
Network: < 2 MB/s
Disk I/O: < 1 MB/s (14 MB/s peak during lazy queu initialization)

[motmot80]

Unfortunately we don't know where to continue to dig deeper.

Any help would be highly appreciated.

Thanks in advance
Thomas

[lukebakken]

Please provide a script we can run to load a 3-node cluster with your exact configuration and message load. The rabbitmqadmin tool would be useful for this. Exporting definitions would also work, but we would need to know how messages are distributed among nodes, as well as information like message size.

I'll also add that I'm not surprised startup is taking this long.

What are the exact specifications of your CPUs and storage devices?

[motmot80]

In our case it's a complex integration testing scenario but we'll try to reduce it to something what's reproducable outside our testing environment. During the restart there was no message traffic. The messages are ~ 30% residing on each node.
What do you think is the most relevant factor for start up? Lazy queue count? Binding count? Message count within lazy queues?

>I'll also add that I'm not surprised startup is taking this long.
@lukebakken:

But RMQ doesn't seem to really take any advantage of the system resources. During the long phases of yawning emptiness inside the
debug log file the CPU, disk and network are almost sleeping. So at startup hardware utilization is at a minimum - if up and running the cluster performs well and makes good use of the hardware.

>What are the exact specifications of your CPUs and storage devices?
CPU: 6 x Xeon E5-2680 v2 @ 2.80GHz less than 25% is used during the "sleeping hour(s)".
Disk: About 60 MB/s less than 1 MB/s is used during the "sleeping hour(s)".
File descriptors: 28793 of 200000
Socket descriptors: 973 of 179910
Erlang processes: 81282 of 1048576

Recently we updated one test node to RMQ 3.8.9 but without improving the startup performance on this node.

[michaelklishin]

Enable debug logging and consider sharing actual logs.

One possible reason with classic mirrored queues is eager sync they use. Use a quorum queue to compare since they only transfer the delta between leader and follower on node startup, if any.

There can be any number of other reasons, a traffic capture and strace output will provide a lot of relevant information

[motmot80]

Enable debug logging and consider sharing actual logs.

One possible reason with classic mirrored queues is eager sync they use. Use a quorum queue to compare since they only transfer the delta between leader and follower on node startup, if any.

There can be any number of other reasons, a traffic capture and strace output will provide a lot of relevant information

We'll try it out immediately. Debug was enabled.

[motmot80]

I reduced the log deleting the repeated messages with a comment.

The relevant parts are marked with the comment NOTHING HAPPENS ?!?.

1. line 276 - 59 minutes without any activity
2. line 325 - 40 minutes without any activity

rabbit@RMQ026_short.log

Although rabbitmq is doing a great job - waiting two hours to get the cluster up and running again after a node fails is a meltdown scenario for us.

Thanks for your help!

[michaelklishin]

Without running a node under strace we can only guess as to what may be going on.

[lukebakken]

Unfortunately that log is not helpful. We will need a way to reproduce this, please see my earlier comment - #2679 (comment)

Also please see @michaelklishin 's comment - #2679 (comment)

[motmot80]

@lukebakken

We isolated the issue saving a state from every node and using an isolated container environment to recover the nodes.
Even tough every node holds the same amount of data and the queues are local lazy queues, it seems to be an cluster related issue.
The first node starts just fine. Only the following nodes joining the cluster have the slow startup performance.

First node: Up within ~ 5 Minutes - no RAM peak
Second node: Up within ~ 42 Minutes - Temporary 200 % RAM peak
Third node: Up within ~ 45 Minutes - Temporary 200 % RAM peak

Very few data was read from storage, but almost 3.2 GB of inter-node network traffic on every node during start up.

[motmot80]

We will now repeat it using strace to isolate more details.

[gerhard]

@mkuratczyk you may want to add extra info here.

[mkuratczyk]

Hi,

I've identified the following two steps that slow down the startup process (and correspond to the "gaps" in your logs):

1. rabbit_binding:recover/0 function that copies the rabbit_durable_route mensia table to rabbit_semi_durable_route. Seems like this can be done much faster and I have an experimental branch you can try. The correctness of the changes is still being discussed but if they are good - this should pretty much get rid of your first "wait" (never took more than a few seconds in my tests but it'd be great if you could confirm).
2. rabbit_binding:recover/2 function. Unfortunately this one is much harder to fix. It's slow mostly when there is a lot of bindings to topic exchanges. Topic exchanges maintain a tree structure that stores the bindings in a way that allows fast message routing based on the topic/routing_key. Unfortunately each binding translates to an insert into that tree structure. Individual inserts are fast but with hundreds of thousands of them, the overall process gets slow. I didn't notice any low-hanging optimizations in this area and while it's probably possible to find a better data structure or algorithm to main these bindings, but that would be a significant undertaking.

In both cases, lack of log messages is justified - these are very fast operations that are only slow because they are repeated hundreds of thousands of times (for each binding) and there is no point logging each execution even at debug level in my opinion (I haven't measured that precisely but these operations were much slower when I added some debug logging).

To test the proposed changes you can deploy a cluster using image: mkuratczyk/rabbitmq-faster-binding-recovery:master and looking for rabbit_binding:recover in the logs (debug logs need to be enabled). For comparison, you can then redeploy with image: mkuratczyk/rabbitmq-measure-recovery:master - this image produces the same debug logs with recovery times but doesn't optimize the recovery. In my test environment, I get a few minutes without optimizations and 1-2 seconds with optimizations.