問(wèn)題描述
MySQL版本：5.7.16，5.7.17高氮，5.7.21
存在多個(gè)半同步從庫(kù)時(shí)，如果參數(shù) rpl_semi_sync_master_wait_for_slave_count=1戳护，啟動(dòng)第1個(gè)半同步從庫(kù)時(shí)可以正常啟動(dòng)嚎货，啟動(dòng)第2個(gè)半同步從庫(kù)后有很大概率 slave_io_thread 停滯（復(fù)制狀態(tài)正常，Slave_IO_Running: Yes，Slave_SQL_Running: Yes软啼，但是完全不同步主庫(kù) binlog ）
復(fù)現(xiàn)步驟
1. 主庫(kù)配置參數(shù)如下：
rpl_semi_sync_master_wait_for_slave_count = 1
rpl_semi_sync_master_wait_no_slave = OFF
rpl_semi_sync_master_enabled = ON
rpl_semi_sync_master_wait_point = AFTER_SYNC
2. 啟動(dòng)從庫(kù)A的半同步復(fù)制 start slave，查看從庫(kù)A復(fù)制正常
3. 啟動(dòng)從庫(kù)B的半同步復(fù)制 start slave贿条，查看從庫(kù)B整以，復(fù)制線程正常悄蕾，但是不同步主庫(kù) binlog
分析過(guò)程
首先弄清楚這個(gè)問(wèn)題 ，需要先結(jié)合MySQL其他的一些狀態(tài)信息番刊，尤其是主庫(kù)的 dump 線程狀態(tài)來(lái)進(jìn)行分析：
1. 從庫(kù)A啟動(dòng)復(fù)制后芹务，主庫(kù)的半同步狀態(tài)已啟動(dòng)：
show global status like '%semi%';
+--------------------------------------------+-----------+
| Variable_name | Value |
+--------------------------------------------+-----------+
| Rpl_semi_sync_master_clients | 1
....
| Rpl_semi_sync_master_status | ON
...
再看主庫(kù)的 dump 線程枣抱，也已經(jīng)啟動(dòng)：
select * from performance_schema.threads where PROCESSLIST_COMMAND='Binlog Dump GTID'\G
*************************** 1. row ***************************
THREAD_ID: 21872
NAME: thread/sql/one_connection
TYPE: FOREGROUND
PROCESSLIST_ID: 21824
PROCESSLIST_USER: universe_op
PROCESSLIST_HOST: 172.16.21.5
PROCESSLIST_DB: NULL
PROCESSLIST_COMMAND: Binlog Dump GTID
PROCESSLIST_TIME: 300
PROCESSLIST_STATE: Master has sent all binlog to slave; waiting for more updates
PROCESSLIST_INFO: NULL
PARENT_THREAD_ID: NULL
ROLE: NULL
INSTRUMENTED: YES
HISTORY: YES
CONNECTION_TYPE: TCP/IP
THREAD_OS_ID: 24093
再看主庫(kù)的 error log佳晶，也顯示 dump 線程（21824）啟動(dòng)成功轿秧，其啟動(dòng)的半同步復(fù)制：
2018-05-25T11:21:58.385227+08:00 21824 [Note] Start binlog_dump to master_thread_id(21824) slave_server(1045850818), pos(, 4)
2018-05-25T11:21:58.385267+08:00 21824 [Note] Start semi-sync binlog_dump to slave (server_id: 1045850818), pos(, 4)
2018-05-25T11:21:59.045568+08:00 0 [Note] Semi-sync replication switched ON at (mysql-bin.000005, 81892061)
2. 從庫(kù)B啟動(dòng)復(fù)制后菇篡，主庫(kù)的半同步狀態(tài)驱还，還是只有1個(gè)半同步從庫(kù) Rpl_semi_sync_master_clients=1：
show global status like '%semi%';
+--------------------------------------------+-----------+
| Variable_name | Value |
+--------------------------------------------+-----------+
| Rpl_semi_sync_master_clients | 1
...
| Rpl_semi_sync_master_status | ON
...
再看主庫(kù)的 dump 線程闷沥，這時(shí)有3個(gè) dump 線程，但是新起的那兩個(gè)一直為 starting 狀態(tài)：
select * from performance_schema.threads where PROCESSLIST_COMMAND='Binlog Dump GTID'\G
*************************** 1. row ***************************
THREAD_ID: 21872
NAME: thread/sql/one_connection
TYPE: FOREGROUND
PROCESSLIST_ID: 21824
PROCESSLIST_USER: universe_op
PROCESSLIST_HOST: 172.16.21.5
PROCESSLIST_DB: NULL
PROCESSLIST_COMMAND: Binlog Dump GTID
PROCESSLIST_TIME: 695
PROCESSLIST_STATE: Master has sent all binlog to slave; waiting for more updates
PROCESSLIST_INFO: NULL
PARENT_THREAD_ID: NULL
ROLE: NULL
INSTRUMENTED: YES
HISTORY: YES
CONNECTION_TYPE: TCP/IP
THREAD_OS_ID: 24093
*************************** 2. row ***************************
THREAD_ID: 21895
NAME: thread/sql/one_connection
TYPE: FOREGROUND
PROCESSLIST_ID: 21847
PROCESSLIST_USER: universe_op
PROCESSLIST_HOST: 172.16.21.6
PROCESSLIST_DB: NULL
PROCESSLIST_COMMAND: Binlog Dump GTID
PROCESSLIST_TIME: 94
PROCESSLIST_STATE: starting
PROCESSLIST_INFO: NULL
PARENT_THREAD_ID: NULL
ROLE: NULL
INSTRUMENTED: YES
HISTORY: YES
CONNECTION_TYPE: TCP/IP
THREAD_OS_ID: 24102*************************** 3. row ***************************
THREAD_ID: 21898
NAME: thread/sql/one_connection
TYPE: FOREGROUND
PROCESSLIST_ID: 21850
PROCESSLIST_USER: universe_op
PROCESSLIST_HOST: 172.16.21.6
PROCESSLIST_DB: NULL
PROCESSLIST_COMMAND: Binlog Dump GTID
PROCESSLIST_TIME: 34
PROCESSLIST_STATE: starting
PROCESSLIST_INFO: NULL
PARENT_THREAD_ID: NULL
ROLE: NULL
INSTRUMENTED: YES
HISTORY: YES
CONNECTION_TYPE: TCP/IP
THREAD_OS_ID: 24966
3 rows in set (0.00 sec)
再看主庫(kù)的 error log享郊，21847 這個(gè)新的 dump 線程一直沒起來(lái)炊琉，直到1分鐘之后從庫(kù) retry ( Connect_Retry 和 Master_Retry_Count 相關(guān))苔咪，主庫(kù)上又啟動(dòng)了1個(gè) dump 線程 21850锰悼，還是起不來(lái)团赏，并且 21847 這個(gè)僵尸線程還停不掉：
2018-05-25T11:31:59.586214+08:00 21847 [Note] Start binlog_dump to master_thread_id(21847) slave_server(873074711), pos(, 4)
2018-05-25T11:32:59.642278+08:00 21850 [Note] While initializing dump thread for slave with UUID <f4958715-5ef3-11e8-9271-0242ac101506>, found a zombie dump thread with the same UUID. Master is killing the zombie dump thread(21847).
2018-05-25T11:32:59.642452+08:00 21850 [Note] Start binlog_dump to master_thread_id(21850) slave_server(873074711), pos(, 4)
3. 到這里我們可以知道，從庫(kù)B slave_io_thread 停滯的根本原因是因?yàn)橹鲙?kù)上對(duì)應(yīng)的 dump 線程啟動(dòng)不了舔清。如何進(jìn)一步分析線程調(diào)用情況丝里？推薦使用 gstack 或者 pstack（實(shí)為gstack軟鏈）來(lái)查看線程調(diào)用棧体谒，其用法很簡(jiǎn)單：gstack <process-id>
4. 看主庫(kù)的 gstack杯聚，可以看到 24102 線程（舊的復(fù)制 dump 線程）堆棧：
Thread 4 (Thread 0x7f0be0549700 (LWP 24102)):
#0 0x00007f0c03c0f1bd in __lll_lock_wait () from /lib64/libpthread.so.0
#1 0x00007f0c03c0ad38 in _L_lock_975 () from /lib64/libpthread.so.0
#2 0x00007f0c03c0ace1 in pthread_mutex_lock () from /lib64/libpthread.so.0
#3 0x00007f0be7588d84 in native_mutex_lock (mutex=0x7f0be778daf0 <ack_receiver+16>) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/include/thr_mutex.h:84
#4 my_mutex_lock (mp=0x7f0be778daf0 <ack_receiver+16>) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/include/thr_mutex.h:182
#5 inline_mysql_mutex_lock (src_line=160, that=<optimized out>, src_file=<optimized out>) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/include/mysql/psi/mysql_thread.h:730
#6 Ack_receiver::remove_slave (this=0x7f0be778dae0 <ack_receiver>, thd=0x7f0b8800fa20) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/plugin/semisync/semisync_master_ack_receiver.cc:160
#7 0x00007f0be7588313 in repl_semi_binlog_dump_end (param=0x7f0be0546e90) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/plugin/semisync/semisync_master_plugin.cc:171
#8 0x0000000000c6013c in Binlog_transmit_delegate::transmit_stop (this=0x1e57040 <delegates_init()::transmit_mem>, thd=<optimized out>, flags=<optimized out>) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/sql/rpl_handler.cc:666
#9 0x0000000000ed1ade in Binlog_sender::cleanup (this=0x7f0be0547540) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/sql/rpl_binlog_sender.cc:175
#10 0x0000000000ed39eb in Binlog_sender::run (this=0x7f0be0547540) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/sql/rpl_binlog_sender.cc:280
#11 0x0000000000ecdd12 in mysql_binlog_send (thd=<optimized out>, log_ident=<optimized out>, pos=<optimized out>, slave_gtid_executed=<optimized out>, flags=<optimized out>) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/sql/rpl_master.cc:415
#12 0x0000000000ed0533 in com_binlog_dump_gtid (thd=0x7f0b8800fa20, packet=0x4 <Address 0x4 out of bounds>, packet_length=<optimized out>) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/sql/rpl_master.cc:399
#13 0x0000000000cf66ac in dispatch_command (thd=0x7f0b8800fa20, com_data=0x7f0be0548de0, command=COM_BINLOG_DUMP_GTID) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/sql/sql_parse.cc:1643
#14 0x0000000000cf7c94 in do_command (thd=0x7f0b8800fa20) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/sql/sql_parse.cc:997
#15 0x0000000000dc2a34 in handle_connection (arg=<optimized out>) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/sql/conn_handler/connection_handler_per_thread.cc:301
#16 0x00000000011cf5f4 in pfs_spawn_thread (arg=0x30f7820) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/storage/perfschema/pfs.cc:2188
#17 0x00007f0c03c08dc5 in start_thread () from /lib64/libpthread.so.0
#18 0x00007f0c028d276d in clone () from /lib64/libc.so.6
可以看到 24966 線程（新的復(fù)制 dump 線程）堆棧：
Thread 12 (Thread 0x7f0be0751700 (LWP 24966)):
#0 0x00007f0c03c0f1bd in __lll_lock_wait () from /lib64/libpthread.so.0
#1 0x00007f0c03c0ad38 in _L_lock_975 () from /lib64/libpthread.so.0
#2 0x00007f0c03c0ace1 in pthread_mutex_lock () from /lib64/libpthread.so.0
#3 0x00007f0be75895cc in native_mutex_lock (mutex=0x7f0be778daf0 <ack_receiver+16>) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/include/thr_mutex.h:84
#4 my_mutex_lock (mp=0x7f0be778daf0 <ack_receiver+16>) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/include/thr_mutex.h:182
#5 inline_mysql_mutex_lock (src_line=138, that=0x7f0be778daf0 <ack_receiver+16>, src_file=<optimized out>) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/include/mysql/psi/mysql_thread.h:730
#6 Ack_receiver::add_slave (this=0x7f0be778dae0 <ack_receiver>, thd=<optimized out>) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/plugin/semisync/semisync_master_ack_receiver.cc:138
#7 0x00007f0be7588405 in repl_semi_binlog_dump_start (param=0x7f0be074ecc0, log_file=0x7f0be074ff20 "", log_pos=4) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/plugin/semisync/semisync_master_plugin.cc:131
#8 0x0000000000c6043a in Binlog_transmit_delegate::transmit_start (this=0x1e57040 <delegates_init()::transmit_mem>, thd=<optimized out>, flags=<optimized out>, log_file=0x7f0be074ff20 "", log_pos=4, observe_transmission=0x7f0be074fecc) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/sql/rpl_handler.cc:652
#9 0x0000000000ed1eb8 in Binlog_sender::init (this=0x7f0be074f540) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/sql/rpl_binlog_sender.cc:111
#10 0x0000000000ed375b in Binlog_sender::run (this=0x7f0be074f540) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/sql/rpl_binlog_sender.cc:200
#11 0x0000000000ecdd12 in mysql_binlog_send (thd=<optimized out>, log_ident=<optimized out>, pos=<optimized out>, slave_gtid_executed=<optimized out>, flags=<optimized out>) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/sql/rpl_master.cc:415
#12 0x0000000000ed0533 in com_binlog_dump_gtid (thd=0x7f0bb0045770, packet=0x4 <Address 0x4 out of bounds>, packet_length=<optimized out>) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/sql/rpl_master.cc:399
#13 0x0000000000cf66ac in dispatch_command (thd=0x7f0bb0045770, com_data=0x7f0be0750de0, command=COM_BINLOG_DUMP_GTID) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/sql/sql_parse.cc:1643
#14 0x0000000000cf7c94 in do_command (thd=0x7f0bb0045770) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/sql/sql_parse.cc:997
#15 0x0000000000dc2a34 in handle_connection (arg=<optimized out>) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/sql/conn_handler/connection_handler_per_thread.cc:301
#16 0x00000000011cf5f4 in pfs_spawn_thread (arg=0x3051570) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/storage/perfschema/pfs.cc:2188
#17 0x00007f0c03c08dc5 in start_thread () from /lib64/libpthread.so.0
兩線程都在等待 Ack_Receiver 的鎖被去，而線程 21875 在持有鎖，等待select：
Thread 15 (Thread 0x7f0bce7fc700 (LWP 21875)):
#0 0x00007f0c028c9bd3 in select () from /lib64/libc.so.6
#1 0x00007f0be7589070 in Ack_receiver::run (this=0x7f0be778dae0 <ack_receiver>) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/plugin/semisync/semisync_master_ack_receiver.cc:261
#2 0x00007f0be75893f9 in ack_receive_handler (arg=0x7f0be778dae0 <ack_receiver>) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/plugin/semisync/semisync_master_ack_receiver.cc:34
#3 0x00000000011cf5f4 in pfs_spawn_thread (arg=0x2d68f00) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/storage/perfschema/pfs.cc:2188
#4 0x00007f0c03c08dc5 in start_thread () from /lib64/libpthread.so.0
#5 0x00007f0c028d276d in clone () from /lib64/libc.so.6
理論上 select 不應(yīng)hang， Ack_receiver 中的邏輯也不會(huì)死循環(huán)坯墨，請(qǐng)教公司大神黃炎進(jìn)行一波源碼分析寂汇。
- semisync_master_ack_receiver.cc 的以下代碼形成了對(duì)互斥鎖的搶占, 餓死了其他競(jìng)爭(zhēng)者：
void Ack_receiver::run()
{
...
while(1)
{
mysql_mutex_lock(&m_mutex);
...
select(...);
...
mysql_mutex_unlock(&m_mutex);
}
...
}
在 mysql_mutex_unlock 調(diào)用后，應(yīng)適當(dāng)增加其他線程的調(diào)度機(jī)會(huì)捣染。
試驗(yàn): 在 mysql_mutex_unlock 調(diào)用后增加 sched_yield();骄瓣，可驗(yàn)證問(wèn)題現(xiàn)象消失。
結(jié)論
- 從庫(kù) slave_io_thread 停滯的根本原因是主庫(kù)對(duì)應(yīng)的 dump thread 啟動(dòng)不了耍攘；
2. rpl_semi_sync_master_wait_for_slave_count=1 時(shí)榕栏，啟動(dòng)第一個(gè)半同步后，主庫(kù) ack_receiver 線程會(huì)不斷的循環(huán)判斷收到的 ack 數(shù)量是否 >= rpl_semi_sync_master_wait_for_slave_count蕾各，此時(shí)判斷為 true扒磁，ack_receiver基本不會(huì)空閑一直持有鎖。此時(shí)啟動(dòng)第2個(gè)半同步式曲，對(duì)應(yīng)主庫(kù)要啟動(dòng)第2個(gè) dump thread妨托，啟動(dòng) dump thread 要等待 ack_receiver 鎖釋放，一直等不到吝羞，所以第2個(gè) dump thread 啟動(dòng)不了兰伤。
這個(gè)問(wèn)題已經(jīng)由我司大神在1月份提交了 bug 和 patch：https://bugs.mysql.com/bug.php?id=89370，已經(jīng)在 5.7.24 版本上修復(fù)了钧排。
