Unreasonably high lock contention when a node restarts and there are a lot of [exclusive] queues delete

[gerhard]

Problem Definition

Given 2 RabbitMQ nodes with 20k connections, 20k channels & 10k non-durable, auto-delete & exclusive queues bound to rmq.topic, when a node stops, there are a lot of Mnesia operations that result in a high number of locks.

#1566 covers a similar problem in a different scenario.

Investigation

Starting the lock counter on rmq1 via lcnt:start() and stopping rmq0, we have observed the following:

lcnt:collect().
lcnt:swap_pid_keys().
lcnt:conflicts([{combine, false}]).
         lock                        id   #tries  #collisions  collisions [%]  time [us]  duration [%]
        -----                       ---  ------- ------------ --------------- ---------- -------------
    run_queue                         4 75376280       675474          0.8961   42973634        1.1433
    run_queue                         2 76148052       645828          0.8481   41306505        1.0989
    run_queue                         3 75579594       643441          0.8513   37995058        1.0108
    run_queue                         1 73601593       606840          0.8245   34935506        0.9294
   pollset_rm                           12931343       309142          2.3906   30411706        0.8091
 drv_ev_state                        12   845032         4378          0.5181    2060488        0.0548
 drv_ev_state                        15   844876         3772          0.4465    1945294        0.0518
 drv_ev_state                        10   841698         3548          0.4215    1926412        0.0513
 drv_ev_state                         4   845841         3719          0.4397    1824964        0.0486
 drv_ev_state                        13  1526500         4595          0.3010    1824145        0.0485
 drv_ev_state                         6   905910         4806          0.5305    1807407        0.0481
 drv_ev_state                         0   907546         4006          0.4414    1792462        0.0477
 drv_ev_state                         8   842934         3896          0.4622    1773568        0.0472
 drv_ev_state                        11   843204         4041          0.4792    1752547        0.0466
 drv_ev_state                         9   840203         3798          0.4520    1686087        0.0449
 drv_ev_state                        14   852544         3691          0.4329    1662951        0.0442
 drv_ev_state                         7   844751         3525          0.4173    1448298        0.0385
 drv_ev_state                         1  1939586         3813          0.1966    1398443        0.0372
       db_tab rabbit_topic_trie_binding   258465        13627          5.2723    1389904        0.0370
 drv_ev_state                         3   842243         3695          0.4387    1344054        0.0358

We found it interesting that the db_tab lock with id rabbit_topic_trie_binding had the highest % of collisions: 5.27%. We looked closer at this specific lock:

lcnt:inspect(db_tab).
   lock                                 id   #tries  #collisions  collisions [%]  time [us]  duration [%] histogram [log2(us)]
  -----                                ---  ------- ------------ --------------- ---------- ------------- ---------------------
 db_tab          rabbit_topic_trie_binding   258465        13627          5.2723    1389904        0.0370 |      ...XXxxXx..........     |
 db_tab                       rabbit_queue 24108834         1366          0.0057     619637        0.0165 |      .XxXXX.............     |
 db_tab connection_stats_coarse_conn_stats 45542002        70886          0.1556     484254        0.0129 |     ....xXXXX.........       |
 db_tab          rabbit_runtime_parameters   313059         1683          0.5376     306599        0.0082 |      ...XXXx............     |
 db_tab               rabbit_reverse_route   192559          191          0.0992     186724        0.0050 |      .....xXX.. .   .. ..    |
 db_tab                queue_process_stats 25757910        35418          0.1375     173666        0.0046 |     ...xXX..............     |
 db_tab                    queue_msg_stats 25772280        28173          0.1093     120092        0.0032 |      ..xX......     ....     |
 db_tab                        queue_stats  7114953        12490          0.1755      90183        0.0024 |      ....xXx....... .  .     |
 db_tab          queue_stats_deliver_stats 25647676         7070          0.0276      28299        0.0008 |      .xXXx.....  .  ..       |
 db_tab                queue_stats_publish 25945360        12697          0.0489      25396        0.0007 |     ...xXx....  .     .      |
 db_tab                       rabbit_route   200922          245          0.1219      23983        0.0006 |       ....xXx...      .      |
 db_tab                    queue_msg_rates 23701654          179          0.0008      16977        0.0005 |     ...xXXx.. .    .  .      |
 db_tab             rabbit_topic_trie_edge  1096182          527          0.0481      11445        0.0003 |      .....xXX.. ..   .       |
 db_tab              rabbit_memory_monitor   171626            0          0.0000       4063        0.0001 |           xXx....            |
 db_tab           file_handle_cache_client   215818            0          0.0000       3419        0.0001 |           .Xx...             |
 db_tab                             ac_tab  9329268           42          0.0005       1315        0.0000 |          . .XXXx.            |
 db_tab                       mnesia_index    67709           78          0.1152        475        0.0000 |       ....xXx.               |
 db_tab                       mnesia_stats   375844          320          0.0851        425        0.0000 |     ..xxXx.....              |
 db_tab            file_handle_cache_stats    72823           56          0.0769        109        0.0000 |       .xXx.   .              |
 db_tab                        mnesia_gvar  7406007           12          0.0002         62        0.0000 |        XX.X   .              |

We are not certain that this is the actual issue. What happens on the restarted node is even more interesting. As this node node boots, it reaches the rabbit_mnesia:init/0 boot step at which point the node acquires 2 locks:

[{{schema,rabbit_durable_route},read,{tid,879886,<6502.2299.18>}},
 {{schema,rabbit_exchange},read,{tid,879887,<6502.2302.18>}}]

The Mnesia Transaction Manager (mnesia_tm) keeps getting restarted because the operations on these specific rows in Mnesia schema table cannot run - maybe. Mnesia is trying to initialize itself internally, on the restarted node, and this is failing. At this point we have the following leads to investigate:

• there is a dynamic table, tracked_connection_on_node_rabbit@rmq0-mnesia-contention that is deleted when the node restarts. We think that this results in a schema table write lock which may prevent the operation that requires those 2 read locks from running - we need to confirm this in Mnesia code.
• Mnesia on the node that was not restarted might not be able to respond to Mnesia running on the restarted node because it is busy deleting a lot of rows from many tables - we could see up to ~35k Mnesia transaction locks on the running node.

As always, there might be other things at play that do not yet understand.

[michaelklishin]

Topic exchanges use a trie for storing bindings, so that's not entirely surprising. Feel free to investigate whether it'd be possible to replace N fine grained locks with a coarse grained one.

[gerhard]

When rmq0 restarts and wants to sync rabbit_durable_route table, Mnesia running on rmq1 cannot send it because this table has an exclusive write lock - read locks cannot be claimed. This table is being cleaned up by first selecting all entries in the table, and then deleting the matching entry - there is only 1. Reading the entire table just to find and delete this 1 entry is highly inefficient when the table has many entries. We will start by making this cleanup operation more efficient.

              {mnesia_info,"Restarting transaction ~w: in ~wms ~w~n",
                  [{tid,1936542,<6502.25051.32>},
                   31742,
                   {cyclic,'rabbit@rmq1-mnesia-contention',
                       {rabbit_durable_route,'______WHOLETABLE_____'},
                       write,write,
                       {tid,1936530,<6502.27196.42>}}]}}

Process that loads all rabbit_durable_route entries to delete 1 entry - <6502.27196.42>

Mnesia controller worker process that continuously restarts its transaction because of the above process' write lock on rabbit_durable_route table - <6502.25051.32>

mnesia_controller that manages the above process

[lukebakken]

Would you look at that, it's even in the comments.

[gerhard]

Yes, we've come across some helpful comments that confirmed our observations and suspicions.

We ended up with a couple of improvements, yet to be committed. You can observe the behaviour of these improvements in https://mnesia-contention.gcp.rabbitmq.com/ (user demo & pass demo). In this environment, nodes are set to restart every 10 minutes in an alternating fashion (e.g. restart rmq0, wait 10 minutes, restart rmq1, wait 10 minutes etc.). With our current changes, nodes restart faster, but there is still a noticeable locking behaviour on the entire cluster - more work to be done.

[lukebakken]

I'll be very interested to see the code changes ... it's what I like to call "Italianate" at the moment 🍝