[MDEV-27568] Parallel async replication hangs on a Galera node Created: 2022-01-21  Updated: 2022-03-18  Resolved: 2022-03-18

Status: Closed
Project: MariaDB Server
Component/s: Galera, Replication
Affects Version/s: 10.4.22, 10.5.13, 10.6.5
Fix Version/s: 10.4.25, 10.5.16, 10.6.8, 10.7.4

Type: Bug Priority: Critical
Reporter: Bryan Bancroft (Inactive) Assignee: Jan Lindström (Inactive)
Resolution: Fixed Votes: 1
Labels: None

Attachments: File my.cnf     File n1.cnf     File n2.cnf     File node1.err    
Issue Links:
Relates
relates to MDEV-6860 Parallel async replication hangs on a... Closed

 Description   

This is still an issue in latest GA. Can be replicated via sysbench

In a setup where a master replicates to a Galera node acting as a slave with slave-parallel-threads > 1, the slave threads hang which brings replication to a halt.

How to reproduce:

Run the attached script on master.
On slave:

MariaDB [test]> show processlist;
 
+----+-------------+-----------------+------+---------+------+--------------------------------------------------------------------------------+------------------+----------+
 
| Id | User        | Host            | db   | Command | Time | State                                                                          | Info             | Progress |
 
+----+-------------+-----------------+------+---------+------+--------------------------------------------------------------------------------+------------------+----------+
 
|  1 | system user |                 | NULL | Sleep   |  840 | NULL                                                                           | NULL             |    0.000 |
 
|  2 | system user |                 | NULL | Sleep   |  840 | wsrep aborter idle                                                             | NULL             |    0.000 |
 
|  5 | system user |                 | NULL | Sleep   |  838 | NULL                                                                           | NULL             |    0.000 |
 
|  6 | system user |                 | NULL | Sleep   |  838 | NULL                                                                           | NULL             |    0.000 |
 
|  7 | system user |                 | NULL | Sleep   |  838 | NULL                                                                           | NULL             |    0.000 |
 
|  8 | system user |                 | NULL | Connect |  263 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |
 
|  9 | system user |                 | NULL | Connect |  263 | closing tables                                                                 | NULL             |    0.000 |
 
| 10 | system user |                 | NULL | Connect |  263 | closing tables                                                                 | NULL             |    0.000 |
 
| 11 | system user |                 | NULL | Connect |  263 | closing tables                                                                 | NULL             |    0.000 |
 
| 12 | root        | localhost:52597 | test | Query   |    0 | init                                                                           | show processlist |    0.000 |
 
| 13 | system user |                 | NULL | Connect |  336 | Waiting for master to send event                                               | NULL             |    0.000 |
 
| 14 | system user |                 | NULL | Connect |  336 | Slave has read all relay log; waiting for the slave I/O thread to update it    | NULL             |    0.000 |
 
+----+-------------+-----------------+------+---------+------+--------------------------------------------------------------------------------+------------------+----------+
 
12 rows in set (0.00 sec)


MariaDB [test]> show slave status\G
 
*************************** 1. row ***************************
 
               Slave_IO_State: Waiting for master to send event
 
                  Master_Host: 127.0.0.1
 
                  Master_User: root
 
                  Master_Port: 15999
 
                Connect_Retry: 60
 
              Master_Log_File: nirbhay-VirtualBox-bin.000001
 
          Read_Master_Log_Pos: 146163
 
               Relay_Log_File: nirbhay-VirtualBox-relay-bin.000002
 
                Relay_Log_Pos: 1463
 
        Relay_Master_Log_File: nirbhay-VirtualBox-bin.000001
 
             Slave_IO_Running: Yes
 
            Slave_SQL_Running: Yes
 
              Replicate_Do_DB: 
          Replicate_Ignore_DB: 
           Replicate_Do_Table: 
       Replicate_Ignore_Table: 
      Replicate_Wild_Do_Table: 
  Replicate_Wild_Ignore_Table: 
                   Last_Errno: 0
 
                   Last_Error: 
                 Skip_Counter: 0
 
          Exec_Master_Log_Pos: 1163
 
              Relay_Log_Space: 146773
 
              Until_Condition: None
 
               Until_Log_File: 
                Until_Log_Pos: 0
 
           Master_SSL_Allowed: No
 
           Master_SSL_CA_File: 
           Master_SSL_CA_Path: 
              Master_SSL_Cert: 
            Master_SSL_Cipher: 
               Master_SSL_Key: 
        Seconds_Behind_Master: 268
 
Master_SSL_Verify_Server_Cert: No
 
                Last_IO_Errno: 0
 
                Last_IO_Error: 
               Last_SQL_Errno: 0
 
               Last_SQL_Error: 
  Replicate_Ignore_Server_Ids: 
             Master_Server_Id: 1
 
               Master_SSL_Crl: 
           Master_SSL_Crlpath: 
                   Using_Gtid: Slave_Pos
 
                  Gtid_IO_Pos: 0-1-1006
 
1 row in set (0.00 sec)

The node also hangs when shutdown.

141009 11:38:17 [Note] ./bin/mysqld: Normal shutdown
 
 
141009 11:38:17 [Note] WSREP: Stop replication
 
141009 11:38:17 [Note] WSREP: Provider disconnect
 
141009 11:38:17 [Note] WSREP: Closing send monitor...
 
141009 11:38:17 [Note] WSREP: Closed send monitor.
 
141009 11:38:17 [Note] WSREP: gcomm: terminating thread
 
141009 11:38:17 [Note] WSREP: gcomm: joining thread
 
141009 11:38:17 [Note] WSREP: gcomm: closing backend
 
141009 11:38:17 [Note] WSREP: view((empty))
 
141009 11:38:17 [Note] WSREP: Received self-leave message.
 
141009 11:38:17 [Note] WSREP: gcomm: closed
 
141009 11:38:17 [Note] WSREP: Flow-control interval: [0, 0]
 
141009 11:38:17 [Note] WSREP: Received SELF-LEAVE. Closing connection.
 
141009 11:38:17 [Note] WSREP: Shifting SYNCED -> CLOSED (TO: 10)
 
141009 11:38:17 [Note] WSREP: RECV thread exiting 0: Success
 
141009 11:38:17 [Note] WSREP: recv_thread() joined.
 
141009 11:38:17 [Note] WSREP: Closing replication queue.
 
141009 11:38:17 [Note] WSREP: Closing slave action queue.
 
141009 11:38:19 [Note] WSREP: waiting for client connections to close: 5

Why this is happening

So the actual issue , Galera sends event at the time of prepare phase
and And creates deadlock.

For example lets us consider the replication A -> B <==> C (A,B
parallel replication optimistic, B,C Galera cluster nodes)
Lets assume 2 inserts(T1 gtid x-x-1 and T2 x-x-2) from master A arrive
to slave B.
2nd insert prepares faster then 1st insert, So it has already sent the
writeset to node C. Now it is the queue waiting for its turn to commit
While the first insert does prepare on galera
(wsrep_run_wsrep_commit), but it is stuck because T2 transaction still
haven't run post_commit on galera
so galera state is still in S_WAITING
T2 cant run post_commit on galera because it is waiting for T1 commit
, T1 cant commit because it is waiting in prepare stage for
transaction T2 to clear the galera state.
Backtrace from gdb

Gtid_seq_no= 2
 
Thread 34 (Thread 0x7fcd966d2700 (LWP 23891)):
 
#0  0x00007fcda6d56415 in pthread_cond_wait@@GLIBC_2.3.2 () from
 
/usr/lib/libpthread.so.0
 
#1  0x00005569d607d380 in safe_cond_wait (cond=0x7fcd854078e8,
 
mp=0x7fcd85407838, file=0x5569d6240360
 
"/home/sachin/10.1/server/include/mysql/psi/mysql_thread.h",
 
line=1154) at /home/sachin/10.1/server/mysys/thr_mutex.c:493
 
#2  0x00005569d5aec4d0 in inline_mysql_cond_wait (that=0x7fcd854078e8,
 
mutex=0x7fcd85407838, src_file=0x5569d6240cb8
 
"/home/sachin/10.1/server/sql/log.cc", src_line=7387) at
 
/home/sachin/10.1/server/include/mysql/psi/mysql_thread.h:1154
 
#3  0x00005569d5afeee5 in MYSQL_BIN_LOG::queue_for_group_commit
 
(this=0x5569d692d7c0 <mysql_bin_log>, orig_entry=0x7fcd966cf440) at
 
/home/sachin/10.1/server/sql/log.cc:7387
 
#4  0x00005569d5aff5c9 in
 
MYSQL_BIN_LOG::write_transaction_to_binlog_events (this=0x5569d692d7c0
 
<mysql_bin_log>, entry=0x7fcd966cf440) at
 
/home/sachin/10.1/server/sql/log.cc:7607
 
#5  0x00005569d5afecff in MYSQL_BIN_LOG::write_transaction_to_binlog
 
(this=0x5569d692d7c0 <mysql_bin_log>, thd=0x7fcd84c068b0,
 
cache_mngr=0x7fcd84c72c70, end_ev=0x7fcd966cf5e0, all=true,
 
using_stmt_cache=true, using_trx_cache=true) at
 
/home/sachin/10.1/server/sql/log.cc:7290
 
#6  0x00005569d5af0ce6 in binlog_flush_cache (thd=0x7fcd84c068b0,
 
cache_mngr=0x7fcd84c72c70, end_ev=0x7fcd966cf5e0, all=true,
 
using_stmt=true, using_trx=true) at
 
/home/sachin/10.1/server/sql/log.cc:1751
 
#7  0x00005569d5af11bb in binlog_commit_flush_xid_caches
 
(thd=0x7fcd84c068b0, cache_mngr=0x7fcd84c72c70, all=true, xid=2) at
 
/home/sachin/10.1/server/sql/log.cc:1859
 
#8  0x00005569d5b045c8 in MYSQL_BIN_LOG::log_and_order
 
(this=0x5569d692d7c0 <mysql_bin_log>, thd=0x7fcd84c068b0, xid=2,
 
all=true, need_prepare_ordered=false, need_commit_ordered=true) at
 
/home/sachin/10.1/server/sql/log.cc:9575
 
#9  0x00005569d5a1ec0d in ha_commit_trans (thd=0x7fcd84c068b0,
 
all=true) at /home/sachin/10.1/server/sql/handler.cc:1497
 
#10 0x00005569d5925e7e in trans_commit (thd=0x7fcd84c068b0) at
 
/home/sachin/10.1/server/sql/transaction.cc:235
 
#11 0x00005569d5b1b1fa in Xid_log_event::do_apply_event
 
(this=0x7fcd8542a770, rgi=0x7fcd85407800) at
 
/home/sachin/10.1/server/sql/log_event.cc:7720
 
#12 0x00005569d5743fa1 in Log_event::apply_event (this=0x7fcd8542a770,
 
rgi=0x7fcd85407800) at /home/sachin/10.1/server/sql/log_event.h:1343
 
#13 0x00005569d573987e in apply_event_and_update_pos_apply
 
(ev=0x7fcd8542a770, thd=0x7fcd84c068b0, rgi=0x7fcd85407800, reason=0)
 
at /home/sachin/10.1/server/sql/slave.cc:3479
 
#14 0x00005569d5739deb in apply_event_and_update_pos_for_parallel
 
(ev=0x7fcd8542a770, thd=0x7fcd84c068b0, rgi=0x7fcd85407800) at
 
/home/sachin/10.1/server/sql/slave.cc:3623
 
#15 0x00005569d597bfbe in rpt_handle_event (qev=0x7fcd85424770,
 
rpt=0x7fcd85421c88) at /home/sachin/10.1/server/sql/rpl_parallel.cc:50
 
#16 0x00005569d597ed57 in handle_rpl_parallel_thread
 
(arg=0x7fcd85421c88) at
 
/home/sachin/10.1/server/sql/rpl_parallel.cc:1258
 
#17 0x00005569d5d42aa4 in pfs_spawn_thread (arg=0x7fcd85415570) at
 
/home/sachin/10.1/server/storage/perfschema/pfs.cc:1861
 
#18 0x00007fcda6d5057f in start_thread () from /usr/lib/libpthread.so.0
 
#19 0x00007fcda5f0f0e3 in clone () from /usr/lib/libc.so.6
 
 
Gtid_seq_no= 1
 
Thread 33 (Thread 0x7fcd9671d700 (LWP 23890)):
 
#0  0x00007fcda6d56415 in pthread_cond_wait@@GLIBC_2.3.2 () from
 
/usr/lib/libpthread.so.0
 
#1  0x00007fcd9e7778ab in gu::Lock::wait (this=0x7fcd9671a0c0,
 
cond=...) at galerautils/src/gu_mutex.hpp:40
 
#2  galera::Monitor<galera::ReplicatorSMM::CommitOrder>::enter
 
(this=this@entry=0x7fcda12d5da0, obj=...) at
 
galera/src/monitor.hpp:124
 
#3  0x00007fcd9e771f28 in galera::ReplicatorSMM::pre_commit
 
(this=0x7fcda12d5000, trx=0x7fcd8507e000, meta=<optimized out>) at
 
galera/src/replicator_smm.cpp:796
 
#5  0x00005569d59864d0 in wsrep_run_wsrep_commit (thd=0x7fcd85006a70,
 
all=true) at /home/sachin/10.1/server/sql/wsrep_hton.cc:492
 
#6  0x00005569d5984d6a in wsrep_prepare (hton=0x7fcda583e270,
 
thd=0x7fcd85006a70, all=true) at
 
/home/sachin/10.1/server/sql/wsrep_hton.cc:208
 
#7  0x00005569d5a1e1b0 in prepare_or_error (ht=0x7fcda583e270,
 
thd=0x7fcd85006a70, all=true) at
 
/home/sachin/10.1/server/sql/handler.cc:1196
 
#8  0x00005569d5a1ea1c in ha_commit_trans (thd=0x7fcd85006a70,
 
all=true) at /home/sachin/10.1/server/sql/handler.cc:1475
 
#9  0x00005569d5925e7e in trans_commit (thd=0x7fcd85006a70) at
 
/home/sachin/10.1/server/sql/transaction.cc:235
 
#10 0x00005569d5b1b1fa in Xid_log_event::do_apply_event
 
(this=0x7fcd8542a570, rgi=0x7fcd85407000) at
 
/home/sachin/10.1/server/sql/log_event.cc:7720
 
#11 0x00005569d5743fa1 in Log_event::apply_event (this=0x7fcd8542a570,
 
rgi=0x7fcd85407000) at /home/sachin/10.1/server/sql/log_event.h:1343
 
#12 0x00005569d573987e in apply_event_and_update_pos_apply
 
(ev=0x7fcd8542a570, thd=0x7fcd85006a70, rgi=0x7fcd85407000, reason=0)
 
at /home/sachin/10.1/server/sql/slave.cc:3479
 
#13 0x00005569d5739deb in apply_event_and_update_pos_for_parallel
 
(ev=0x7fcd8542a570, thd=0x7fcd85006a70, rgi=0x7fcd85407000) at
 
/home/sachin/10.1/server/sql/slave.cc:3623
 
#14 0x00005569d597bfbe in rpt_handle_event (qev=0x7fcd85423870,
 
rpt=0x7fcd85421a80) at /home/sachin/10.1/server/sql/rpl_parallel.cc:50
 
#15 0x00005569d597ed57 in handle_rpl_parallel_thread
 
(arg=0x7fcd85421a80) at
 
/home/sachin/10.1/server/sql/rpl_parallel.cc:1258
 
#16 0x00005569d5d42aa4 in pfs_spawn_thread (arg=0x7fcd854152f0) at
 
/home/sachin/10.1/server/storage/perfschema/pfs.cc:1861
 
#17 0x00007fcda6d5057f in start_thread () from /usr/lib/libpthread.so.0
 
#18 0x00007fcda5f0f0e3 in clone () from /usr/lib/libc.so.6


Generated at Thu Feb 08 09:53:54 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.