Message store not cleaning up .rdq files

[johanrhodin]

We've seen an issue with at least two completely different customers where a large amount of data is never cleared from the vhost's msg_store_persistent-folder.

When this happens queue data as measured by total_message_bytes remains low (say 1GiB), but data on disk in .rdq files grows without GC, to hundreds or even thousands of GiB. The number of .rdq files and file descriptors also tend to increase.

Case A

Erlang version 25.3.2.7
RabbitMQ version 3.12.6 (but also seen in 3.11.x)
Messages sizes: 1kB to 20-40MiB messages
Cqv1 and Cqv2 tested, both have the issue. (non-mirrored in both cases)

Case B

RabbitMQ version 3.10.1
Message sizes: 0kB-2MiB
Cqv1 with lazy-queues (non-mirrored)

Known Mitigations/workarounds:

• Restarting RabbitMQ causes the message store to clear up all the files that are not used.

• Increase queue_index_embed_msgs_below to large values (such as 16MiB), so that very few messages are written to msg_store_persistent

• Updating to 3.13.0-rc.4 could potentially solve this issue too, since it has some changes to the message store.

Reproduction

Analyzing the .idx/.qi/.qs and checking the matching .rdq-files we can see that almost all rdq files should be deleted (but, in extreme cases, ~one hundred thousand of them the are not)

We haven't (yet) been able to reproduce this issue but have tried along these lines:

• Reduce queue_index_embed_msgs_below so that almost everything is written to the message store
• Reduce the size of .rdq files (from default 16MB) to smaller values
• Set up publishers that publish some large messages (several MiB), some small messages, and randomly ack some of them.

[michaelklishin]

You don't have to wait for 3.13 to enable CQv2. They have shipped in 3.11 and have been greatly improved in 3.12.

You can even switch to CQv2 and then switch back by using a policy.

I don't think we will spend much time on CQv1 going forward.

[johanrhodin]

For Case A cqv2 has been used in 3.12.6

[lhoguin]

The (per-vhost) message store is a separate component so going from v1 to v2 won't do much. The changes in 3.13 apply equally to v1 and v2.

[lhoguin]

My only guess would be that something happened that leads the message store to not receive / ignore the delete commands, or that combining files failed somehow and stopped triggering. Tracing the rabbit_msg_store_gc process (after the issue happens, before restarting) would likely tell us much about the latter.

But I would expect that kind of failure to produce logs of some kind.

[gomoripeti]

what we've seen tracing the GC process is

• that it has a few (~10-70) Thunks in #state.on_action that are postponed deletes, but the list is not growing, and the safe_deletes eventually succeed
• it has a long message queue of delete requests (in its internal gen_server2 queue) (10Ks) and it cannot keep up with the influx of delete requests. It can delete about 10 rdq files/sec
• eventually when traffic lowers the GC process can slowly work through its backlog and delete the files (but it can take 12-24h and needs a huge disk to accommodate). So its not that the GC process is stuck on something indefinitely

Compared to the deletes when the issue does not happen GC is doing exclusively combines (no deletes)

What we don't know is what causes the GC process to fail to keep up with the garbage collection work. Is it one sudden event or something slowly affecting the process. The total number of messages on the server is stable, we don't see huge (up or down) spikes of any message count related metric.

Noting that affected clusters are all single node (Johan already mentioned non-mirroring)

[lukas8219]

One note about your comment @gomoripeti :

Is it one sudden event or something slowly affecting the process. - We've had that issue several time ( at least more than 5 ) and most of them were caused by huge backlogs and sudden consumption OR deletion. (No deletion was ever made)

It was not uncommon to have build ups like 150K-250K messages, scaling the infra up above and beyond to rapidly consume them.

AFAIR last time, we had 500K messages and we deleted (EDIT: we shoveled them to another queue) those messages via Management UI. Right after it, the disk issue started happening

So maybe, that contributes into this theory of gen_server2 queue backlog build up?

[gomoripeti]

@lhoguin as you know the classic queue implementation inside-out may I have some questions about some details:

1. the GC process sometimes cannot immediately delete an rdq file because in rabbit_msdg_store:safe_file_delete/3 (3.12.12) sometimes there is a close entry in the FileHandleEts table for that file. When does that close entry get there and when is it removed? (I guess they are added and removed by the queue processes which are the "msg store clients")
2. I also see that the safe_file_delete/3 is removed in 3.13 (which is great :) ) why is that or what made it possible?
3. rabbit_msg_store:delete_file/2 calls scan_and_vacuum_message_file/2 (main) which reads in the whole file including msg bodies. (This is the case both in 3.12.x and on main/3.13). This is in order to delete msg_location entries from the msg store Index. Wouldn't it be enough to read it from the Index which MsgIds are located in the deleted rdq file (just like the new load_and_vacuum_message_file)? If MsgIds need to be read from a file, would it make sense to have a special scan function which only reads in the MsgIds (and metadata) from the rdq file and seek-skips the Msg bodies? (In my experience this reading of the full rdq file is the slowest part of the delete_file operation) This way delete_file maybe could be made faster (I did not measure) and also less memory would be used.

[lhoguin]

1. This has to do with the file_handle_cache. I am not sure why this happens here exactly but likely the file was "soft closed" meaning the handle is still open. The file cannot be deleted when it is. It's another FHC optimisation that comes to bite us. Since I started work on v2 and now the message store in 3.13 one of the goal was to remove FHC and 3.13 no longer use FHC in normal store operations so we know there won't be FDs open for these files.
2. See 1.
3. If we delete the file we can just delete all entries for this file from ets using a match delete operation. It can be expensive too but might be better. I haven't touched file deletion much in 3.13 because that wasn't the goal and I didn't expect performance issues from this. But it can definitely be improved. In 3.13 the files typically get compacted before being deleted so this is less likely to be an issue though.

[gomoripeti]

thank you, Loic! very good insights

[johanrhodin]

FTR I'm adding a link to a discussion about a similar, but maybe different, issue that was fixed in 3.13.1: https://github.com/rabbitmq/rabbitmq-server/discussions/ #10681

In the linked discussion cqv2 message stores were working correctly in 3.12.x but not in 3.13.0.