Memory allocation spikes on first message published after hours of inactivity

[motmot80]

Description

After 4-5 h of inactivity a tiny amount of published messages leads to a doubling the RAM usage.

Reproduction

1. Fill up a cluster with 150 million messages to 50k queues (local non-lazy queues - 16 k queues each node)
   a) each node allocates about 14 GB of 32 GB RAM
   b) publish rates > 10 000 msg/sec fan out exchange are working fine and stable
   c) Filled within 3 hours
2. 4-5 h of total inactivity (no RAM churn visible)
3. Publish some messages f.e. about 50 (no fan out messages - only routed to a single queue)

Expected

The cluster performs like 4 hours before using about the same amount of RAM (14 GB).

Actual

Right after the first messages are published each cluster node allocates another 15 GB RAM!! within 5 minutes hitting the high-watermark.

Log (Info level)

No log entries till the memory high watermark is hit.

Rabbit MQ setup

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

Reproduction setup

Type	Count	Description
Queues (lazy or non-lazy local )	50 000	16 666 per node
Messages ready	150 000 000	~ 14 GB RAM

System load before error

CPU(user): < 10 %
CPU(kernel): < 10 %
RAM: < 15 GB (~50 %)

System load after "resuming"

CPU(user): < 70 %
CPU(kernel): < 15 %
RAM: < 30 GB (~95 %)

[lukebakken]

Hello, and thanks for taking the time to report this.

Since it seems as though you can easily reproduce this behavior, could you please do so using the latest version of Erlang (23.2.3) and RabbitMQ? (3.8.12-beta.1).

It would also be extremely helpful if you could export your cluster definitions to a file and attach them so we can see exactly how everything is set up. Thanks!

[motmot80]

Unfortunately it crashed after a while and we had to reset it, because of the extremly slow startup times.
We'll try to reproduce the issue tomorrow exporting the definitions while the cluster ist running.

[michaelklishin]

Please use PerfTest to do so so that the exact settings (e.g. whether messages are published as persistent or not) is known https://rabbitmq.github.io/rabbitmq-perf-test/stable/htmlsingle/

[michaelklishin]

Total amount of memory used here is not particularly interesting, a breakdown over time (something that Prometheus and Grafana dashboards support out of the box) and allocator tweaks would be significantly more relevant.

[motmot80]

Will an extract from https://grafana.com/grafana/dashboards/11350 be sufficient?
We did no allocator tweaks yet.

[motmot80]

> It would also be extremely helpful if you could export your cluster definitions to a file and attach them so we can see exactly how everything is set up. Thanks!

We are filling the test environment right now to reproduce the issue, but actually rabbitmq-admin export doesn't seem to work. We'll try again when the message rampup is finished.

*** Error getting HTTP response:
...
version, status, reason = self._read_status()
  File "/usr/lib64/python2.6/httplib.py", line 397, in _read_status
    raise BadStatusLine(line)
BadStatusLine

Alternatively the clear text representation of our definition:

Id	Type	Settings	Count	Description	Payload/Messages
1	Local Queue	queue-master-locator:client-local,max-length-bytes: 6291456, message-ttl: 604800000	65,000	21,666 per node	30,000,000 messages
2	HA Queue	dead-letter-exchange:deadletter-XXX,ha-mode:exactly,ha-params:2, ha-promote-on-failure:always, ha-promote-on-shutdown: when-synced	1		0 messages
5	Local Queue	dead-letter-exchange:deadletter-XXX, message-ttl:604800000	3		0 messages
4	Exchanges	Topic	21	Bound to 65,000 queues	800,000 bindings (routing-key)
5	Exchanges	FanOut	5	Bound to local queues	1 bindings

[michaelklishin]

You can ask the node what uses the memory.

[motmot80]

F.e. rabbitmqctl and rabbitmq-diagnostic observer unfortunately no longer worked.

[michaelklishin]

observer is intrusive and rabbitmq-diagnostics memory_breakdown is not (it queries runtime allocator stats once).

[motmot80]

Thanks for the information. We'll try this having reproduced the issue.

[motmot80]

We filled up the nodes again. Less but bigger messages (~40M)
We'll let it run for serveral hours.

rabbitmq admin ui

memory breakdown (node 1)

rabbitmq-diagnostics memory_breakdown

queue_procs: 6.8185 gb (43.28%)
allocated_unused: 3.0144 gb (19.14%)
mnesia: 2.1065 gb (13.37%)
msg_index: 1.7146 gb (10.88%)
plugins: 0.6976 gb (4.43%)
mgmt_db: 0.5675 gb (3.6%)
other_ets: 0.3485 gb (2.21%)
other_proc: 0.2705 gb (1.72%)
metrics: 0.0801 gb (0.51%)
other_system: 0.0622 gb (0.4%)
code: 0.0262 gb (0.17%)
connection_other: 0.0259 gb (0.16%)
binary: 0.0169 gb (0.11%)
connection_readers: 0.0018 gb (0.01%)
atom: 0.0016 gb (0.01%)
connection_channels: 0.0001 gb (0.0%)
quorum_ets: 0.0 gb (0.0%)
connection_writers: 0.0 gb (0.0%)
queue_slave_procs: 0.0 gb (0.0%)
quorum_queue_procs: 0.0 gb (0.0%)
reserved_unallocated: 0.0 gb (0.0%)

erlang grafana memory board (node 1)

[motmot80]

We were able to reproduce the issue after 4-8h of inactivity followed by publishing messages. During this resume "event" the RabbitMQ grafana memory statistics are showing that every RabbitMQ node "tries" to allocate almost 70 GB at peak level. The VMs have 32 GB RAM.

[Metric].Allocated Used: 66.76 GB
[Allocated by Allocator Type] eheap_alloc: 76.46 GB
[eheap_alloc]: Singleblock used: 60.76 GB

As you can see there's not much going on till a smalll amount of messages are produced:

Unfortunately we not only have a simulated testing issue with this. It already happened in production.

Any help would be greatly appreciated.
Thomas

[gerhard]

We have re-created both setups as escalated - 3-nodes & single node - and we were not able to reproduce the described problem. More details have been shared in the escalation ticket, as requested.

[motmot80]

Just guessing from the hole of despair:

Could it be that queues are somehow "woken up" because they are linked to the same topic exchange even if the routing key doesn't match this queue?
And that this event could cause f.e. a garbage collection on all of this queues because of inactivity (low credit, missing consumers or something else). Topic exhange 1 is bound to every queue. This is also the case for topic exhange 2 but with twice as many bindings.

Topic 1 - 50K Bindings
Topic 2 - 110K Bindings
...

Everything seems to be fine and deterministic but after a few hours ...

[gerhard]

Queues wake up periodically for stats, every 10 seconds or so. When they do so, the memory grows from 900KB to 1.7MB, but not above in our tests. There is more that was shared via the escalation, as requested. The problem is that we were not able to reproduce, even though we have used the same definitions, and followed the exact steps as described. We were able to hit a few other issues, but none that you are reporting. We have all environments still around, able to demonstrate, and dig as deep as we need to get to the bottom of this.

I have asked for a meeting today, but maybe it was too short notice. I am available Thursday - 18 Feb - so let's block as much time as is needed to sort this out directly. I would suggest a morning meeting so that we can extend or resume if needed. Please coordinate with support, I will be available.

[motmot80]

I wasn't able to find anything new within the support ticket (269116). But maybe this is my fault - the tool is VERY confusing...

I really appreciate your help very much and I really know (from a developer perspective) how hard it is to validate something which cannot be reproduced or isolated.

I will cancel all my appointments on Thursday and occupy our testing environment. I will instruct the colleagues to fill the cluster according to the case shown so you can research live.

Looking forward to our conversation
Thomas

[gerhard]

Talk to you in ~1h 👍🏻

[gerhard]

This has been resolved part of VESC-1002 (private).

The public resolution is here: erlang/otp#4571 (comment)

If you agree @motmot80, please mark this comment as the answer 👍🏻