3.11: Classic Mirrored Queues (v1, v2) sometimes keeps accumulating messages in memory

[luos]

Describe the bug

Hi,

Seems like sometimes Classic Queue v2 does not push messages to disk. I do not think the issue comes from mirroring - but it seems to be easier to reproduce.

Reproduction steps

1. Use RabbitMQ 3.11.16, Erlang 25.3.2
2. Apply policy

3. Run perftest

bin/runjava com.rabbitmq.perf.PerfTest -h $RABBITMQ_HOST -x 1 -y 1 --queue-pattern-from 1 --queue-pattern-to 1 --queue-pattern "perftest.durable.classic-%d-3$(date +'%s')" -ad false --time 300 -f persistent --size 10000 --consumer-rate 1 --qos 100 --pmessages 1000000

4. On the queue master everything looks more or less OK:

5. On the Overview page it is visible that one of the nodes is stuck in memory alarm / close to memory alarm
   

6. We can take a look at the state of the queue mirror on node 76:

                 {passthrough,rabbit_variable_queue,
                               {vqstate,{0,[],[]},
                                        {0,[],[]},
                                        {delta,undefined,0,0,undefined},
                                        {0,[],[]},
                                        {949681,
                                         [{msg_status,949883,<<"z|N\377\305"...>>,
                                                      {basic_message,{resource,<<...>>,...},[<<...>>],{...},...},
                                                      true,true,rabbit_msg_store,true,...},
                                          {msg_status,949882,
                                                      <<5,249,141,185,...>>,
                                                      {basic_message,{resource,...},[...],...},
                                                      true,true,rabbit_msg_store,...},
                                          {msg_status,949881,<<"\373\306\311o\376\366#\323=\303\376o"...>>,
                                                      {basic_message,{...},...},
                                                      true,true,...},

7. Taking a look at the leader of the queue

                  {passthrough,rabbit_variable_queue,
                                  {vqstate,{151467,
                                            [{msg_status,949883,<<"z|N\377\305"...>>,
                                                         {basic_message,...},
                                                         true,...},
                                             {msg_status,949882,<<5,...>>,{...},...},
                                             {msg_status,949881,<<...>>,...},
                                             {msg_status,949880,...},
                                             {msg_status,...},
                                             {...}|...],
                                            [{msg_status,798417,<<"?\\\340f"...>>,{...},...},
                                             {msg_status,798418,<<...>>,...}]},
                                           {136099,
                                            [{msg_status,798416,<<"H\323\bx"...>>,undefined,...},
                                             {msg_status,798415,<<...>>,...},
                                             {msg_status,798414,...},
                                             {msg_status,...},
                                             {...}|...],
                                            [{msg_status,662318,<<...>>,...},
                                             {msg_status,662319,...},
                                             {msg_status,...},
                                             {...}|...]},
                                           {delta,180224,482094,0,662318},
                                           {2152,
                                            [{msg_status,180223,...},{msg_status,...},{...}|...],
                                            [{msg_status,...},{...}|...]},
                                           {177869,[{msg_status,...},{...}|...],[{...}|...]},
                                           949884,303,
                                           {0,...},
                                           {...},...}},
                     #{},[],#{},15000},

Expected behavior

Memory usage goes down after stopping of publishers.

Additional context

Let me know if anything else is needed, seems to happen to me about 50% with mirrored queues, and I remember seeing it with non-mirrored queues but I can't reproduce. The same applies to CQv1, I think the same happens but I could not reproduce it again.

Update: after submitting the ticket I reproduced it with V1, mirrored. Same issue happened.

[michaelklishin]

Classic mirrored queues are close to the point where all issues reported for them will be up to their users to investigate and fix.

[lhoguin]

There's no guarantee for messages to be pushed to disk prior to 3.12 unless you're using lazy queues or are using publisher confirms. This is simply how classic queues work. The queue will move messages to disk when the node is under memory pressure, not when you stop publishers.

[luos]

There is no guarantee, but you can see that node 76 is under memory pressure, as it just came out of high watermark, probably because of some garbage was collected.

I am not sure how publish confirms are related to this discussion, because I'd think those would be independent of a queue's memory usage?

[luos]

From your comments in the code and PRs I understood that CQv2 was never really keeping messages in memory, which seems to be not the case here.

[lhoguin]

CQv2 before 3.12 will write more data to disk but that doesn't mean the queue won't keep the messages also in memory.

Did you check the logs to confirm that memory alarm was triggered? All the messages seem to be in q4 which is message and metadata in memory and is consistent with the CMQ slave behavior, it just puts message there under this scenario. It's possible there's a bug but we can't know that without checking in the logs that the memory alarm was in fact triggered.

[luos]

Yes, it was triggered. I think paging was starting at the paging_ratio in older versions, and I'd expect that all mirrors / master behaves more or less the same, but in this case there is an outlier node, even though they have the same specs and config.

[michaelklishin]

So the question is, can this be reproduced in 3.12.0-rc.3. We won't delay 3.12.0 over a CMQ-specific behavior.

I have enqueued 120M of messages with PerfTest in 4 non-mirrored CQv2s. Peak memory footprint was about 1.2 GiB, and when all publishers were stopped, in about a minute (queue hibernation kicking in?) the memory consumption dropped to less than 300 MiB.