| Bug #99440 | Threads of MTS Slave randomly stuck | ||
|---|---|---|---|
| Submitted: | 5 May 2020 7:16 | Modified: | 3 Dec 2020 13:37 |
| Reporter: | Mershad Irani | Email Updates: | |
| Status: | Duplicate | Impact on me: | |
| Category: | MySQL Server: Replication | Severity: | S2 (Serious) |
| Version: | 5.7.26 | OS: | Linux |
| Assigned to: | CPU Architecture: | x86 | |
| Tags: | logical_clock | ||
[5 May 2020 7:19]
Mershad Irani
Details of Troubleshooting
Attachment: bug_99440_details.txt (text/plain), 16.12 KiB.
[5 May 2020 13:44]
MySQL Verification Team
Hi, Have you tried reproducing this on the latest 5.7? or 8.0? thanks Bogdan
[6 May 2020 13:37]
MySQL Verification Team
Hi, I am unable to reproduce this on 5.7.30. Kind regards Bogdan
[7 May 2020 10:44]
MySQL Verification Team
Repeated on 5.7.28...
Attachment: bug99440_5.7.28_outputs.txt (text/plain), 103.79 KiB.
[7 May 2020 11:33]
MySQL Verification Team
Repeated on 5.7.30...
Attachment: bug99440_5.7.30_outputs.txt (text/plain), 137.56 KiB.
[7 May 2020 11:36]
MySQL Verification Team
easier to repeat with innodb_lock_wait_timeout=1
[7 May 2020 12:46]
MySQL Verification Team
also affects 8.0.20
Attachment: bug99440_8.0.20_outputs.txt (text/plain), 208.65 KiB.
[24 Sep 2020 7:48]
Venkatesh Prasad Venugopal
Looks like all the below bugs are duplicates of each other. Bug #87796 Commit_order_manager can't terminate MTS worker properly when deadlock happens Bug #89247 Deadlock with MTS when slave_preserve_commit_order = ON. Bug #95249 stop slave permanently blocked Bug #99440 Threads of MTS Slave randomly stuck Here is the root cause for the bug. When --slave-preserve-commit-order is enabled on slave and if the waiting thread has locked the rows which are needed by the thread executing the previous transaction(as per their order in the relay log), then the innodb deadlock detection algorithm detects the deadlock between workers and will ask the waiting thread to rollback (only if its sequence number is lesser than that of the waiting thread). When this happens, the waiting thread wakes up from the cond_wait(SPCO) and it gets to know that it was asked to rollback by its preceding transaction as it was holding a lock that is needed by the other transaction to progress. It then rolls back its transaction so that the the preceding transaction can be committed and retries the transaction. The above logic sometimes caused the worker thread to miss the signals resulting in the replica server to hang. One of such hang is mentioned below. Consider a replica server which is configured with slave_parallel_workers=3, slave_parallel_type=LOGICAL_CLOCK, slave_preserve_commit_order=1 and slave_transaction_retries=0. When MTS is enabled, it is quite possible that workers execute out of order causing the below state. Worker 1 - Processing the events of Transaction T1 Worker 2 - Executed Transaction T2 and is waiting for T1 to commit. Worker 3 - Processing the events of Transaction T3 1. If T1 and T2 are modifying same rows in InnodB, then the worker 1 detects deadlock and asks worker 2 to rollback by signalling. 2. Worker 2 wakes up from the cond_wait. It gets to know that it was asked to roll back by the other transaction and returns with an error. 3. Worker 2 rolls back the transaction and comes to the retry part of the code and checks the value of slave_transaction_retries. Since it is 0, it returns from the handle_slave_worker loop and enters the error handling part. 4. As part of error handling, Worker 2 notifies the co-ordinator that it is exiting, and then calls report_rollback() function to unregister itself from the SPCO queue. 5. While executing report_rollback(), Worker 2 will again enter wait_for_its_turn(). But before entering the wait, it checks the commit_order_deadlock flag. Since the flag is already set, Worker2 immediately returns from the function with error. 6. Co-ordinator thread gets this information and sets the rli->abort_slave=1 to stop replication and waits till all workers exit. 7. Worker 2 exits. There is no worker 2 from here onwards. Now the status is, Worker 1 - Processing the events of Transaction T1 Worker 2 - Not running. Worker 3 - Processing the events of Transaction T3 8. Now the worker 1 proceeds and executes the transaction and enters the Commit_order_manager::wait_for_its_turn. 9. Worker 1 finds out that the previous worker(Worker 2) failed because of an error. 10. Worker 1 signals next transaction/worker to proceed. 11. Worker 3 executes the transaction and enters the Commit_order_manager::wait_for_its_turn. 12. Worker 1 rolls back the transaction and eventually exits. 13. There will be no one to signal Worker 3 and thus waits forever. This resulted in a system hang as the co-ordinator thread will be waiting for the worker thread to finish and the worker thread will be waiting for the signal to proceed with the commit. mysql> show processlist; +----+-------------+-----------------+------+---------+------+-----------------------------------------+ | Id | User | Host | db | Command | Time | State | Info | Rows_sent | Rows_examined | +----+-------------+-----------------+------+---------+------+-----------------------------------------+ | 2 | root | localhost:55708 | test | Query | 0 | starting | show processlist | 0 | 0 | | 3 | system user | | NULL | Connect | 107 | Waiting for master to send event | NULL | 0 | 0 | | 4 | system user | | NULL | Connect | 77 | Waiting for workers to exit | NULL | 0 | 0 | | 7 | system user | | NULL | Connect | 84 | Waiting for preceding transaction to commit | NULL | 0 | 0 | +----+-------------+-----------------+------+---------+------+-----------------------------------------+
[24 Sep 2020 7:54]
Venkatesh Prasad Venugopal
Contributed patch on top of 5.7.31 (*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.
Contribution: 0001-MTS-deadlock-with-slave_preserve_commit_order.patch (text/x-patch), 37.06 KiB.
[24 Sep 2020 8:03]
MySQL Verification Team
Thank you, Venu for the contribution. regards, Umesh
[29 Sep 2020 5:20]
Venkatesh Prasad Venugopal
Contributed patch on top of 8.0.21 (*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.
Contribution: 0001-MTS-deadlock-with-slave_preserve_commit_order-8.0.patch (text/x-patch), 37.04 KiB.
[3 Dec 2020 13:37]
Srinivasarao Ravuri
Closing this bug as a duplicate to https://bugs.mysql.com/bug.php?id=87796
Description: We randomly see slave parallel worker threads dead-latch each other with slave_parallel_type set to logical_clock. I have attached the details to the bug. Disclaimer: I have masked some of the information on this bug and the stack traces for security reasons. 1. InnoDB monitor 2. Processlist 3. performance_schema.threads 4. Slave Status 5. Contents of the relay logs at the position where the workers were stuck. 6. pstack 7. my.cnf setting 8. Table definition How to repeat: I was able to partially reproduce the issue in my case. 1. On the master. 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) mysqlslap -uaaa -pxxx -hx.x.x.x --query=' INSERT IGNORE INTO table_name (d_id, b_id, c_id, a_id) VALUES ('20123', 1234203, 3, 12345212);' --create-schema=efg --iterations=100 --concurrency=100; Benchmark Average number of seconds to run all queries: 0.238 seconds Minimum number of seconds to run all queries: 0.070 seconds Maximum number of seconds to run all queries: 2.046 seconds Number of clients running queries: 100 Average number of queries per client: 1 2. On the slave we saw a lock wait timeout, but eventually 2 threads deadlocked. Master_SSL_Verify_Server_Cert: No Last_IO_Errno: 0 Last_IO_Error: Last_SQL_Errno: 1205 Last_SQL_Error: Coordinator stopped because there were error(s) in the worker(s). The most recent failure being: Worker 15 failed executing transaction 'ANONYMOUS' at master log mysql-bin-changelog.000020, end_log_pos 24400. See error log and/or performance_schema.replication_applier_status_by_worker table for more details about this failure or others, if any. Replicate_Ignore_Server_Ids: Master_Server_Id: 327350796 Master_UUID: a8bf8179-8939-11ea-b223-12a81901bcad Master_Info_File: mysql.slave_master_info SQL_Delay: 0 mysql> show processlist; +----+-------------+---------------------+------+---------+------+---------------------------------------------+------------------+ | Id | User | Host | db | Command | Time | State | Info | +----+-------------+---------------------+------+---------+------+---------------------------------------------+------------------+ | 3 | abc | xyz:38316 | NULL | Sleep | 6 | | NULL | | 4 | system user | | NULL | Connect | 1331 | Waiting for master to send event | NULL | | 5 | system user | | NULL | Connect | 670 | Waiting for workers to exit | NULL | | 19 | system user | | NULL | Connect | 1093 | Waiting for preceding transaction to commit | NULL | | 20 | system user | | NULL | Connect | 1093 | Waiting for preceding transaction to commit | NULL | | 22 | abc | localhost | NULL | Sleep | 1 | | NULL | | 26 | aaa | xyz:54900 | NULL | Query | 0 | starting | show processlist | +----+-------------+---------------------+------+---------+------+---------------------------------------------+------------------+ 7 rows in set (0.00 sec) | | 15 | NULL | OFF | ANONYMOUS | 1205 | Worker 15 failed executing transaction 'ANONYMOUS' at master log mysql-bin-changelog.000020, end_log_pos 24400; Lock wait timeout exceeded; try restarting transaction | 2020-04-28 11:47:35 | Pstacks were similar except that in this case on of the Thread 6 (Thread 0x2b8a9178a700 (LWP 10164)): #0 0x00002b8a86e116d5 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 #1 0x0000000000ef1540 in native_cond_wait (mutex=0x2bbc469f2d00, cond=0x2bbc469f2d30) at /mysqlinclude/thr_cond.h:140 #2 my_cond_wait (mp=0x2bbc469f2d00, cond=0x2bbc469f2d30) at /mysqlinclude/thr_cond.h:195 #3 inline_mysql_cond_wait (src_file=0x1785288 "/mysqlsql/rpl_slave.cc", src_line=7100, mutex=0x2bbc469f2d00, that=0x2bbc469f2d30) at /mysqlinclude/mysql/psi/mysql_thread.h:1180 #4 slave_stop_workers (rli=rli@entry=0x2b8a87a1f800, mts_inited=mts_inited@entry=0x2b8a91789946) at /mysqlsql/rpl_slave.cc:7100 #5 0x0000000000ef355e in handle_slave_sql (arg=arg@entry=0x2bbaef385000) at /mysqlsql/rpl_slave.cc:7542 #6 0x00000000012ead59 in pfs_spawn_thread (arg=0x2bbc45f20020) at /mysqlstorage/perfschema/pfs.cc:2190 #7 0x00002b8a86e0ddc5 in start_thread () from /lib64/libpthread.so.0 #8 0x00002b8a87118c9d in clone () from /lib64/libc.so.6 Thread 5 (Thread 0x2b8abed50700 (LWP 10207)): #0 0x00002b8a86e116d5 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 #1 0x0000000000f09025 in native_cond_wait (mutex=0x2bbc462650c0, cond=0x2bbc4626f8b0) at /mysqlinclude/thr_cond.h:140 #2 my_cond_wait (mp=0x2bbc462650c0, cond=0x2bbc4626f8b0) at /mysqlinclude/thr_cond.h:195 #3 inline_mysql_cond_wait (src_file=0x178ab30 "/mysqlsql/rpl_slave_commit_order_manager.cc", src_line=93, mutex=0x2bbc462650c0, that=0x2bbc4626f8b0) at /mysqlinclude/mysql/psi/mysql_thread.h:1180 #4 Commit_order_manager::wait_for_its_turn (this=0x2bbc462650c0, worker=0x2bbc469efa40, all=all@entry=true) at /mysqlsql/rpl_slave_commit_order_manager.cc:93 #5 0x0000000000ecd8d1 in MYSQL_BIN_LOG::ordered_commit (this=this@entry=0x1fa2280 <mysql_bin_log>, thd=thd@entry=0x2bbc4a00d000, all=all@entry=true, skip_commit=<optimized out>) at /mysqlsql/binlog.cc:9559 #6 0x0000000000eceef3 in MYSQL_BIN_LOG::commit (this=0x1fa2280 <mysql_bin_log>, thd=0x2bbc4a00d000, all=<optimized out>) at /mysqlsql/binlog.cc:8851 #7 0x0000000000895e3f in ha_commit_trans (thd=thd@entry=0x2bbc4a00d000, all=all@entry=true, ignore_global_read_lock=ignore_global_read_lock@entry=false) at /mysqlsql/handler.cc:1799 #8 0x0000000000da3b59 in trans_commit (thd=0x2bbc4a00d000) at /mysqlsql/transaction.cc:239 #9 0x0000000000e9c8d9 in non-virtual thunk to Xid_log_event::do_commit(THD*) () at /mysqlsql/log_event.cc:11730 #10 0x0000000000e9ad06 in Xid_apply_log_event::do_apply_event_worker (this=0x2bbc4a3521e8, w=0x2bbc469efa40) at /mysqlsql/log_event.cc:7192 #11 0x0000000000f04a73 in Slave_worker::read_and_apply_events (this=this@entry=0x2bbc469efa40, start_relay_number=start_relay_number@entry=19, start_relay_pos=start_relay_pos@entry=23928, end_relay_number=end_relay_number@entry=19, end_relay_pos=end_relay_pos@entry=24265) at /mysqlsql/rpl_rli_pdb.cc:2080 #12 0x0000000000f04f37 in Slave_worker::retry_transaction (this=this@entry=0x2bbc469efa40, start_relay_number=start_relay_number@entry=19, start_relay_pos=start_relay_pos@entry=23928, end_relay_number=19, end_relay_pos=24265) at /mysqlsql/rpl_rli_pdb.cc:2004 #13 0x0000000000f0653a in slave_worker_exec_job_group (worker=worker@entry=0x2bbc469efa40, rli=rli@entry=0x2b8a87a1f800) at /mysqlsql/rpl_rli_pdb.cc:2673 #14 0x0000000000ee7ba3 in handle_slave_worker (arg=arg@entry=0x2bbc469efa40) at /mysqlsql/rpl_slave.cc:6207 #15 0x00000000012ead59 in pfs_spawn_thread (arg=0x2bbc46287120) at /mysqlstorage/perfschema/pfs.cc:2190 #16 0x00002b8a86e0ddc5 in start_thread () from /lib64/libpthread.so.0 #17 0x00002b8a87118c9d in clone () from /lib64/libc.so.6 Thread 4 (Thread 0x2b8abed91700 (LWP 10209)): #0 0x00002b8a86e116d5 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 #1 0x0000000000f09025 in native_cond_wait (mutex=0x2bbc462650c0, cond=0x2bbc4626f8f8) at /mysqlinclude/thr_cond.h:140 #2 my_cond_wait (mp=0x2bbc462650c0, cond=0x2bbc4626f8f8) at /mysqlinclude/thr_cond.h:195 #3 inline_mysql_cond_wait (src_file=0x178ab30 "/mysqlsql/rpl_slave_commit_order_manager.cc", src_line=93, mutex=0x2bbc462650c0, that=0x2bbc4626f8f8) at /mysqlinclude/mysql/psi/mysql_thread.h:1180 #4 Commit_order_manager::wait_for_its_turn (this=this@entry=0x2bbc462650c0, worker=worker@entry=0x2bbc469f4ec0, all=all@entry=true) at /mysqlsql/rpl_slave_commit_order_manager.cc:93 #5 0x0000000000f09327 in Commit_order_manager::report_rollback (this=0x2bbc462650c0, worker=0x2bbc469f4ec0) at /mysqlsql/rpl_slave_commit_order_manager.cc:143 #6 0x0000000000f033df in Slave_worker::slave_worker_ends_group (this=this@entry=0x2bbc469f4ec0, ev=ev@entry=0x2bbc4a352668, error=error@entry=1) at /mysqlsql/rpl_rli_pdb.cc:1236 #7 0x0000000000f065e6 in slave_worker_exec_job_group (worker=worker@entry=0x2bbc469f4ec0, rli=rli@entry=0x2b8a87a1f800) at /mysqlsql/rpl_rli_pdb.cc:2737 #8 0x0000000000ee7ba3 in handle_slave_worker (arg=arg@entry=0x2bbc469f4ec0) at /mysqlsql/rpl_slave.cc:6207 #9 0x00000000012ead59 in pfs_spawn_thread (arg=0x2bbc462874a0) at /mysqlstorage/perfschema/pfs.cc:2190 #10 0x00002b8a86e0ddc5 in start_thread () from /lib64/libpthread.so.0 #11 0x00002b8a87118c9d in clone () from /lib64/libc.so.6 Difference between my repro and the actual occurence. 1. In the repro Last_SQL_Errno was 1205(lock wait timeout exceeded), where as during the actual occurrence of the issue, it was 0. 2. In the repro, once thread was stuck on Commit_order_manager::report_rollback, where as the other thread was stuck on MYSQL_BIN_LOG::ordered_commit. However, in the actual occurrence of the issue, both threads were waiting on MYSQL_BIN_LOG::ordered_commit I did come across bugs which may be related. https://bugs.mysql.com/bug.php?id=87796 https://bugs.mysql.com/bug.php?id=93761 https://bugs.mysql.com/bug.php?id=95249