1. Output of InnoDB Monitor ---TRANSACTION 20941948292, ACTIVE (PREPARED) 61512 sec 6 lock struct(s), heap size 1136, 3 row lock(s), undo log entries 1 MySQL thread id 137, OS thread handle 47889736075008, query id 2433298713 Waiting for preceding transaction to commit ---TRANSACTION 20941948289, ACTIVE (PREPARED) 61512 sec 7 lock struct(s), heap size 1136, 4 row lock(s), undo log entries 1 MySQL thread id 138, OS thread handle 47889736341248, query id 2433298707 Waiting for preceding transaction to commit 2. Process List mysql> show processlist ; +----------+-----------------+-----------------+------+---------+---------+---------------------------------------------+------------------+ | Id | User | Host | db | Command | Time | State | Info | +----------+-----------------+-----------------+------+---------+---------+---------------------------------------------+------------------+ | 1 | event_scheduler | abc | NULL | Daemon | 1 | Waiting for next activation | NULL | | 119 | system user | | NULL | Connect | 1106131 | Waiting for master to send event | NULL | | 120 | system user | | NULL | Connect | 60399 | Waiting for workers to exit | NULL | | 137 | system user | | NULL | Connect | 60401 | Waiting for preceding transaction to commit | NULL | | 138 | system user | | NULL | Connect | 60401 | Waiting for preceding transaction to commit | NULL | | 162 | abc | abc:26447 | NULL | Sleep | 11 | | NULL | | 2869456 | abc | abc | NULL | Sleep | 1 | | NULL | | 24876238 | abc | abc | NULL | Query | 0 | starting | show processlist | +----------+-----------------+-----------------+------+---------+---------+---------------------------------------------+------------------+ 8 rows in set (0.00 sec) 3. Output of performance_schema.threads *************************** 2. row *************************** THREAD_ID: 145 NAME: thread/sql/slave_sql TYPE: FOREGROUND PROCESSLIST_ID: 120 PROCESSLIST_USER: abc PROCESSLIST_HOST: xyz PROCESSLIST_DB: NULL PROCESSLIST_COMMAND: Connect PROCESSLIST_TIME: 62403 PROCESSLIST_STATE: Waiting for workers to exit PROCESSLIST_INFO: NULL PARENT_THREAD_ID: 32 ROLE: NULL INSTRUMENTED: YES HISTORY: YES CONNECTION_TYPE: NULL THREAD_OS_ID: 12100 *************************** 3. row *************************** THREAD_ID: 162 NAME: thread/sql/slave_worker TYPE: FOREGROUND PROCESSLIST_ID: 137 PROCESSLIST_USER: abc PROCESSLIST_HOST: xyz PROCESSLIST_DB: NULL PROCESSLIST_COMMAND: Connect PROCESSLIST_TIME: 62405 PROCESSLIST_STATE: Waiting for preceding transaction to commit PROCESSLIST_INFO: NULL PARENT_THREAD_ID: 145 ROLE: NULL INSTRUMENTED: YES HISTORY: YES CONNECTION_TYPE: NULL THREAD_OS_ID: 12137 *************************** 4. row *************************** THREAD_ID: 163 NAME: thread/sql/slave_worker TYPE: FOREGROUND PROCESSLIST_ID: 138 PROCESSLIST_USER: abc PROCESSLIST_HOST: xyz PROCESSLIST_DB: NULL PROCESSLIST_COMMAND: Connect PROCESSLIST_TIME: 62405 PROCESSLIST_STATE: Waiting for preceding transaction to commit PROCESSLIST_INFO: NULL PARENT_THREAD_ID: 145 ROLE: NULL INSTRUMENTED: YES HISTORY: YES CONNECTION_TYPE: NULL THREAD_OS_ID: 12138 Output of information_schema.innodb_trx ========================================= mysql> select trx_id,trx_state,trx_started,trx_mysql_thread_id,trx_rows_modified from information_schema.innodb_trx; +-------------+-----------+---------------------+---------------------+-------------------+ | trx_id | trx_state | trx_started | trx_mysql_thread_id | trx_rows_modified | +-------------+-----------+---------------------+---------------------+-------------------+ | 20941948292 | RUNNING | 2020-04-13 16:33:36 | 137 | 1 | | 20941948289 | RUNNING | 2020-04-13 16:33:36 | 138 | 1 | +-------------+-----------+---------------------+---------------------+-------------------+ 2 rows in set (0.00 sec) 4. Show Slave Status shows that the Exec_Master_Log_Pos does not progress. Below are the relevant fields. Slave_IO_State: Waiting for master to send event Connect_Retry: 60 Master_Log_File: mysql-bin-changelog.020920 Read_Master_Log_Pos: 59065084 Relay_Log_File: relaylog.013908 Relay_Log_Pos: 25967290 Relay_Master_Log_File: mysql-bin-changelog.020682 Slave_IO_Running: Yes Slave_SQL_Running: Yes Last_Errno: 0 Last_Error: worker thread retried transaction 10 time(s) in vain, giving up. Consider raising the value of the slave_transaction_retries variable. Skip_Counter: 0 Exec_Master_Log_Pos: 25967171 Relay_Log_Space: 21808957737 Seconds_Behind_Master: 60392 Last_IO_Errno: 0 Last_IO_Error: Last_SQL_Errno: 0 Last_SQL_Error: worker thread retried transaction 10 time(s) in vain, giving up. Consider raising the value of the slave_transaction_retries variable. Master_Server_Id: 1354915806 Master_UUID: 7838d1c5-51c0-11ea-8e7b-0a6674135bad SQL_Delay: 0 SQL_Remaining_Delay: NULL Slave_SQL_Running_State: Waiting for workers to exit Master_Retry_Count: 86400 Last_SQL_Error_Timestamp: 200413 16:32:45 5. On further investigation, we found the below two statements from the relay log files that were responsible for dead-latching each other. Note that these are single valued inserts. Also we are inserting duplicate unique key values. (gdb) info args this = 0x2bbfb4deef80 start_relay_number = 13908 start_relay_pos = 26008749 end_relay_number = 13908 end_relay_pos = 26009113 | relaylog.013908 | 26008749 | Anonymous_Gtid | 1354915806 | 26008695 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS' | | relaylog.013908 | 26008814 | Query | 1354915806 | 26008774 | BEGIN | | relaylog.013908 | 26008893 | Intvar | 1354915806 | 26008806 | INSERT_ID=12345943 | | relaylog.013908 | 26008925 | Query | 1354915806 | 26008994 | use `efg`; INSERT IGNORE INTO table_name (d_id, b_id, c_id, a_id) VALUES ('20123', 1234203, 3, 12345212) | | relaylog.013908 | 26009113 | Xid | 1354915806 | 26009025 | COMMIT /* xid=2757308321 */ | * 104 (gdb) info args this = 0x2bbfb4de24c0 start_relay_number = 13908 start_relay_pos = 26008354 end_relay_number = 13908 end_relay_pos = 26008718 | relaylog.013908 | 26008354 | Anonymous_Gtid | 1354915806 | 26008300 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS' | | relaylog.013908 | 26008419 | Query | 1354915806 | 26008379 | BEGIN | | relaylog.013908 | 26008498 | Intvar | 1354915806 | 26008411 | INSERT_ID=12345933 | | relaylog.013908 | 26008530 | Query | 1354915806 | 26008599 | use `efg`; exit | | relaylog.013908 | 26008718 | Xid | 1354915806 | 26008630 | COMMIT /* xid=2757308160 */ 6. Pstack The queries were not blocked by any other statement. It was a single valued "INSERT IGNORE INTO" table name. Thread 105 (Thread 0x2b8dfcf86700 (LWP 12100)): #0 0x00002b8df25ce6d5 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 #1 0x0000000000ef1540 in native_cond_wait (mutex=0x2bbfb4de5780, cond=0x2bbfb4de57b0) at /mysql/include/thr_cond.h:140 #2 my_cond_wait (mp=0x2bbfb4de5780, cond=0x2bbfb4de57b0) at /mysql/include/thr_cond.h:195 #3 inline_mysql_cond_wait (src_file=0x1785288 "/mysql/sql/rpl_slave.cc", src_line=7100, mutex=0x2bbfb4de5780, that=0x2bbfb4de57b0) at /mysql/include/mysql/psi/mysql_thread.h:1180 #4 slave_stop_workers (rli=rli@entry=0x2b8df31fc800, mts_inited=mts_inited@entry=0x2b8dfcf85946) at /mysql/sql/rpl_slave.cc:7100 #5 0x0000000000ef355e in handle_slave_sql (arg=arg@entry=0x2bbe5a9d2800) at /mysql/sql/rpl_slave.cc:7542 #6 0x00000000012ead59 in pfs_spawn_thread (arg=0x2bbfb253d1e0) at /mysql/storage/perfschema/pfs.cc:2190 #7 0x00002b8df25cadc5 in start_thread () from /lib64/libpthread.so.0 #8 0x00002b8df28d5c9d in clone () from /lib64/libc.so.6 Thread 104 (Thread 0x2b8e32b50700 (LWP 12137)): #0 0x00002b8df25ce6d5 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 #1 0x0000000000f09025 in native_cond_wait (mutex=0x2bbfb3c650c0, cond=0x2bbfb3c79488) at /mysql/include/thr_cond.h:140 #2 my_cond_wait (mp=0x2bbfb3c650c0, cond=0x2bbfb3c79488) at /mysql/include/thr_cond.h:195 #3 inline_mysql_cond_wait (src_file=0x178ab30 "/mysql/sql/rpl_slave_commit_order_manager.cc", src_line=93, mutex=0x2bbfb3c650c0, that=0x2bbfb3c79488) at /mysql/include/mysql/psi/mysql_thread.h:1180 #4 Commit_order_manager::wait_for_its_turn (this=0x2bbfb3c650c0, worker=0x2bbfb4de24c0, all=all@entry=true) at /mysql/sql/rpl_slave_commit_order_manager.cc:93 #5 0x0000000000ecd8d1 in MYSQL_BIN_LOG::ordered_commit (this=this@entry=0x1fa2280 , thd=thd@entry=0x2bbfb820d000, all=all@entry=true, skip_commit=) at /mysql/sql/binlog.cc:9559 #6 0x0000000000eceef3 in MYSQL_BIN_LOG::commit (this=0x1fa2280 , thd=0x2bbfb820d000, all=) at /mysql/sql/binlog.cc:8851 #7 0x0000000000895e3f in ha_commit_trans (thd=thd@entry=0x2bbfb820d000, all=all@entry=true, ignore_global_read_lock=ignore_global_read_lock@entry=false) at /mysql/sql/handler.cc:1799 #8 0x0000000000da3b59 in trans_commit (thd=0x2bbfb820d000) at /mysql/sql/transaction.cc:239 #9 0x0000000000e9c8d9 in non-virtual thunk to Xid_log_event::do_commit(THD*) () at /mysql/sql/log_event.cc:11730 #10 0x0000000000e9ad06 in Xid_apply_log_event::do_apply_event_worker (this=0x2bbfb9ddd1e8, w=0x2bbfb4de24c0) at /mysql/sql/log_event.cc:7192 #11 0x0000000000f04a73 in Slave_worker::read_and_apply_events (this=this@entry=0x2bbfb4de24c0, start_relay_number=start_relay_number@entry=13908, start_relay_pos=start_relay_pos@entry=26008354, end_relay_number=end_relay_number@entry=13908, end_relay_pos=end_relay_pos@entry=26008718) at /mysql/sql/rpl_rli_pdb.cc:2080 #12 0x0000000000f04f37 in Slave_worker::retry_transaction (this=this@entry=0x2bbfb4de24c0, start_relay_number=start_relay_number@entry=13908, start_relay_pos=start_relay_pos@entry=26008354, end_relay_number=13908, end_relay_pos=26008718) at /mysql/sql/rpl_rli_pdb.cc:2004 #13 0x0000000000f0653a in slave_worker_exec_job_group (worker=worker@entry=0x2bbfb4de24c0, rli=rli@entry=0x2b8df31fc800) at /mysql/sql/rpl_rli_pdb.cc:2673 #14 0x0000000000ee7ba3 in handle_slave_worker (arg=arg@entry=0x2bbfb4de24c0) at /mysql/sql/rpl_slave.cc:6207 #15 0x00000000012ead59 in pfs_spawn_thread (arg=0x2bbfb3c8cba0) at /mysql/storage/perfschema/pfs.cc:2190 #16 0x00002b8df25cadc5 in start_thread () from /lib64/libpthread.so.0 #17 0x00002b8df28d5c9d in clone () from /lib64/libc.so.6 Thread 103 (Thread 0x2b8e32b91700 (LWP 12138)): #0 0x00002b8df25ce6d5 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 #1 0x0000000000f09025 in native_cond_wait (mutex=0x2bbfb3c650c0, cond=0x2bbfb3c794d0) at /mysql/include/thr_cond.h:140 #2 my_cond_wait (mp=0x2bbfb3c650c0, cond=0x2bbfb3c794d0) at /mysql/include/thr_cond.h:195 #3 inline_mysql_cond_wait (src_file=0x178ab30 "/mysql/sql/rpl_slave_commit_order_manager.cc", src_line=93, mutex=0x2bbfb3c650c0, that=0x2bbfb3c794d0) at /mysql/include/mysql/psi/mysql_thread.h:1180 #4 Commit_order_manager::wait_for_its_turn (this=0x2bbfb3c650c0, worker=0x2bbfb4deef80, all=all@entry=true) at /mysql/sql/rpl_slave_commit_order_manager.cc:93 #5 0x0000000000ecd8d1 in MYSQL_BIN_LOG::ordered_commit (this=this@entry=0x1fa2280 , thd=thd@entry=0x2bbfb840d000, all=all@entry=true, skip_commit=) at /mysql/sql/binlog.cc:9559 #6 0x0000000000eceef3 in MYSQL_BIN_LOG::commit (this=0x1fa2280 , thd=0x2bbfb840d000, all=) at /mysql/sql/binlog.cc:8851 #7 0x0000000000895e3f in ha_commit_trans (thd=thd@entry=0x2bbfb840d000, all=all@entry=true, ignore_global_read_lock=ignore_global_read_lock@entry=false) at /mysql/sql/handler.cc:1799 #8 0x0000000000da3b59 in trans_commit (thd=0x2bbfb840d000) at /mysql/sql/transaction.cc:239 #9 0x0000000000e9c8d9 in non-virtual thunk to Xid_log_event::do_commit(THD*) () at /mysql/sql/log_event.cc:11730 #10 0x0000000000e9ad06 in Xid_apply_log_event::do_apply_event_worker (this=0x2bbfb9dde9e8, w=0x2bbfb4deef80) at /mysql/sql/log_event.cc:7192 #11 0x0000000000f04a73 in Slave_worker::read_and_apply_events (this=this@entry=0x2bbfb4deef80, start_relay_number=start_relay_number@entry=13908, start_relay_pos=start_relay_pos@entry=26008749, end_relay_number=end_relay_number@entry=13908, end_relay_pos=end_relay_pos@entry=26009113) at /mysql/sql/rpl_rli_pdb.cc:2080 #12 0x0000000000f04f37 in Slave_worker::retry_transaction (this=this@entry=0x2bbfb4deef80, start_relay_number=start_relay_number@entry=13908, start_relay_pos=start_relay_pos@entry=26008749, end_relay_number=13908, end_relay_pos=26009113) at /mysql/sql/rpl_rli_pdb.cc:2004 #13 0x0000000000f0653a in slave_worker_exec_job_group (worker=worker@entry=0x2bbfb4deef80, rli=rli@entry=0x2b8df31fc800) at /mysql/sql/rpl_rli_pdb.cc:2673 #14 0x0000000000ee7ba3 in handle_slave_worker (arg=arg@entry=0x2bbfb4deef80) at /mysql/sql/rpl_slave.cc:6207 #15 0x00000000012ead59 in pfs_spawn_thread (arg=0x2bbfb3c8cf20) at /mysql/storage/perfschema/pfs.cc:2190 #16 0x00002b8df25cadc5 in start_thread () from /lib64/libpthread.so.0 #17 0x00002b8df28d5c9d in clone () from /lib64/libc.so.6 7. my.cnf Setting binlog_format=mixed slave_preserve_commit_order=1 slave_parallel_workers=16 slave_paralley_type=logical_clock gtid_mode=off binlog_order_commmits=1 log_slave_updates=ON 8. Table Definition: mysql> show create table efg.table_name \G *************************** 1. row *************************** Table: table_name Create Table: CREATE TABLE `table_name` ( `id` bigint(20) NOT NULL AUTO_INCREMENT, `a_id` bigint(20) NOT NULL, `b_id` bigint(20) NOT NULL, `c_id` smallint(5) NOT NULL, `d_id` varchar(255) NOT NULL DEFAULT '', `created_at` datetime NOT NULL, PRIMARY KEY (`id`), UNIQUE KEY `unique_table_name` (`a_id`,`b_id`), KEY `index_b` (`b_id`) ) ENGINE=InnoDB AUTO_INCREMENT=12345933 DEFAULT CHARSET=utf8 COMMENT='table definition' 1 row in set (0.00 sec)