4.0.8: msg_store_persistent on disk footprint spikes

[przdev]

Describe the bug

We’re running RabbitMQ 4.0.8 on Erlang/OTP 27.3.2. Over the last few weeks we’ve observed that msg_store_persistent (the on-disk store used by persistent queues) will at random times explode to 400 GiB+, even though the sum total of all messages in all queues at that moment is consistently around 3 GiB. This causes our broker node to rapidly fill its filesystem and eventually go into disk alarms or crash.

Queues setting:
x-queue-type:classic durable: true queue storage version: 2

Disk Usage:
`394G ./msg_store_persistent
256M ./msg_store_transient
3.9G ./queues
398G .

`

Reproduction steps

1. Don't know flow, it happens randomly

Expected behavior

Ideally it should consume less disk space as there is not much messages.

Additional context

No response

[michaelklishin]

@przdev we cannot suggest anything with this much information. #13233 and #13430 are two relevant discussions/changes. They took weeks to investigate, and a few screenshots really isn't much to work with.

How can we reproduce your workload with PerfTest? How large are the messages? Are you absolutely sure that your consumers do not consume large messages and then never acknowledge them?

4.0.x is out of community support, so any potential changes will ship in 4.1.x.

[przdev]

@michaelklishin

we're using single node setup on k8s with bitnami image (docker.io/bitnami/rabbitmq:4.0.8-debian-12-r2)

config:
cluster_name = v3-pipeline-rabbitmq
cluster_formation.peer_discovery_backend = rabbit_peer_discovery_k8s
cluster_formation.k8s.host = kubernetes.default
cluster_formation.k8s.address_type = hostname
cluster_formation.k8s.service_name = v3-pipeline-rabbitmq-headless
cluster_formation.k8s.hostname_suffix = .v3-pipeline-rabbitmq-headless.rabbitmq.svc.cluster.local
cluster_formation.node_cleanup.interval = 10
cluster_formation.node_cleanup.only_log_warning = true
cluster_partition_handling = autoheal
queue_master_locator = min-masters
loopback_users.user = false
prometheus.tcp.port = 9419
tcp_listen_options.backlog = 128
tcp_listen_options.nodelay = true
tcp_listen_options.linger.on = true
tcp_listen_options.linger.timeout = 0
tcp_listen_options.keepalive = false

message size: mainly from few kb to 4 mb

Are you absolutely sure that your consumers do not consume large messages and then never acknowledge them?
yes, consumer always ack messages

[mkuratczyk]

What do you do when this happens? Does it just go away (disk space gets freed up) or you delete something or restart RabbitMQ perhaps?

How often does it happen?

Please save a full list of files (ls -lR) in the message store when it happens.

[przdev]

it happens randomly without delete or restart etc.

How often does it happen?
this time: it happend after 21 day,
first it happend twice a week (this time it wasn't on 4.0.8 and we updated to 4.0.8 by assuming #13430 issue ) but again happen after 21 days,

currently in msg_store_persistent there is 64548 files, here is head and tail sorted by date (attached top 100 head and tail)
file_list.txt

usually storage stays idle (less than 10 GB), but when this happen it grows like 30-40GB in hour and it fills until out of space.

[przdev]

day wise counts

      1 2025-04-16
      1 2025-04-17
     10 2025-04-18
      4 2025-04-19
      1 2025-04-21
      6 2025-04-22
      1 2025-04-23
      1 2025-04-24
      3 2025-04-25
      2 2025-04-27
   1848 2025-04-28
   4605 2025-04-29
   2949 2025-04-30
  11960 2025-05-01
      8 2025-05-02
      5 2025-05-03
      5 2025-05-04
     27 2025-05-05
     22 2025-05-06
      7 2025-05-07
     18 2025-05-08
     17 2025-05-09
      6 2025-05-10
      2 2025-05-11
     10 2025-05-12
      9 2025-05-13
     24 2025-05-14
     12 2025-05-15
      4 2025-05-16
      2 2025-05-17
      2 2025-05-18
     19 2025-05-19
      8 2025-05-20
     16 2025-05-21
   3391 2025-05-22
  40030 2025-05-23

[mkuratczyk]

Please enable debug logs (for a few minutes should suffice) and share the logs

Also, I was asking what you did to resolve the situation - I understand it happens unexpectedly, but did it also go away on its own?

[przdev]

Also, I was asking what you did to resolve the situation - I understand it happens unexpectedly, but did it also go away on its own?

unfortunately no, it didn't resolve automatically, so we delete volume and create again in k8s

[gomoripeti]

we had a similar case yesterday. RMQ: 4.0.9 Erlang 27.3.3

What I've seen when I looked at the issue, is that the msg_store GC process was constantly working deleting rdq files, but some files could take up to 5 seconds (and new rdq files were created in a higher rate) The GC process was busy in rabbit_msg_store:scan_file_for_valid_messages/2 and often it hit the code path for scan_next_byte, ie it scans the rdq file byte by byte if it found an invalid message.
I don't know why a message was considered invalid, could be:

• duplicate message towards the end of the file after compaction (https://github.com/rabbitmq/rabbitmq-server/blob/v4.1.0/deps/rabbit/src/rabbit_msg_store.erl#L1521)
• duplicate message in a different file because of fan-out (https://github.com/rabbitmq/rabbitmq-server/blob/v4.1.0/deps/rabbit/src/rabbit_msg_store.erl#L2148)
• not present in the index at all, not sure how this can happen during normal operation (not recovery) (https://github.com/rabbitmq/rabbitmq-server/blob/v4.1.0/deps/rabbit/src/rabbit_msg_store.erl#L2156)

Not sure if the fan-out is applicable in our case, but it sounds plausible: the traffic is routed via a topic exchange, each message always into 2 queues

Whatever is the cause, a message deemed invalid can cause the deletion of an rdq file much slower and cause such build-up issues.

(Will dig up some graphs soon)

[mkuratczyk]

We spoke about this a while back:
https://github.com/rabbitmq/rabbitmq-server/blob/v4.1.0/deps/rabbit/src/rabbit_msg_store.erl#L2125

I've certainly seen situations where this was the bottleneck. I've never seen and don't recall anyone reporting a matching failure that would occur if scan_and_vacuum_message_file found valid messages in a file that was about to be deleted, so perhaps it's time to just remove this assertion?

[gomoripeti]

yes I remember this being mentioned as a bottleneck. (I've only seen the msg store GC process lagging on older 3.x version until now (and that was probably because of slow combine ops), now I've seen it on 4.x with my own eyes)

I agree I haven't ever seen a matching failure, so I'm +1 on removing.

(noting that during a a recovery after an unclean shutdown, all the rdq files which contain only deleted messages are super slow to scan, as the index_lookup returns not_found for messages that are not in any queue any more (the reconstructed index cannot contain entries with ref_count=0) and that means they are considered invalid. Probably if the GC process is not lagging during normal operation then there cannot be that many rdq files with only deleted messages, but in the above issue I reported an unclean recovery with about 500 rdq files took half an hour. Also noting a lagging GC process is more problematic than just a slow startup, the later cannot cause disk leak, it's just inconvenience or downtime)

[gomoripeti]

actually it is not only an assertion as it also does vacuuming, so it cannot be just removed. It also removes the entries from the index which belong to the given rdq file. There used to be an ets:select to gather such entries but because the key is not the file index it could be slow if there are many entries in the index. But there could be a "secondary index", another ets table that maps from rdq file -> msgId, that could be used for efficient lookup. (Then actually the assertion can even be kept (like there used to be

rabbitmq-server/deps/rabbit/src/rabbit_msg_store.erl

Line 2001 in 32816c0

load_and_vacuum_message_file(File, State) ->

) if an efficient version of load_and_vacuum_message_file is used)