深度分析 | 多從庫時半同步複製不工做的BUG分析

原創做者：胡呈清 黃炎

---

前  言

本文是由愛可生運維團隊出品的「MySQL專欄」系列文章，內容來自於運維團隊一線實戰經驗，涵蓋MySQL各類特性的實踐，優化案例，數據庫架構，HA，監控等，有掃雷功效。

愛可生開源社區持續運營維護的小目標：

• 每週至少推送一篇高質量技術文章

• 每個月研發團隊發佈開源組件新版

• 每一年1024開源一款企業級組件

• 2019年至少25場社區活動

歡迎你們持續關注～

 

問題描述

MySQL版本：5.7.16，5.7.17，5.7.21

存在多個半同步從庫時，若是參數 rpl_semi_sync_master_wait_for_slave_count=1，啓動第1個半同步從庫時能夠正常啓動，啓動第2個半同步從庫後有很大機率 slave_io_thread 停滯,（複製狀態正常，Slave_IO_Running: Yes，Slave_SQL_Running: Yes，可是徹底不一樣步主庫 binlog ）

 

復現步驟

1. 主庫配置參數以下：

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. 啓動從庫A的半同步複製 start slave，查看從庫A複製正常

3. 啓動從庫B的半同步複製 start slave，查看從庫B，複製線程正常，可是不一樣步主庫 binlog

 

分析過程

首先弄清楚這個問題 ，須要先結合MySQL其餘的一些狀態信息，尤爲是主庫的 dump 線程狀態來進行分析：

1. 從庫A啓動複製後，主庫的半同步狀態已啓動：

show global status like '%semi%';
+--------------------------------------------+-----------+
| Variable_name | Value |
+--------------------------------------------+-----------+
| Rpl_semi_sync_master_clients | 1 
....
| Rpl_semi_sync_master_status | ON 
...

再看主庫的 dump 線程，也已經啓動：

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

再看主庫的 error log，也顯示 dump 線程（21824）啓動成功，其啓動的半同步複製：

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. 從庫B啓動複製後，主庫的半同步狀態，仍是隻有1個半同步從庫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 
...

再看主庫的 dump 線程，這時有3個 dump 線程，可是新起的那兩個一直爲 starting 狀態：

再看主庫的 error log，21847 這個新的 dump 線程一直沒起來，直到1分鐘以後從庫 retry ( Connect_Retry 和 Master_Retry_Count 相關)，主庫上又啓動了1個 dump 線程 21850，仍是起不來，而且 21847 這個殭屍線程還停不掉：

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. 到這裏咱們能夠知道，從庫B  slave_io_thread 停滯的根本緣由是由於主庫上對應的 dump 線程啓動不了。**如何進一步分析線程調用狀況？推薦使用 gstack 或者 pstack（實爲gstack軟鏈）來查看線程調用棧，其用法很簡單：gstack <process-id>

4. 看主庫的 gstack，能夠看到 24102 線程（舊的複製 dump 線程）堆棧：

能夠看到 24966 線程（新的複製 dump 線程）堆棧：

兩線程都在等待 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 不該hang， Ack_receiver 中的邏輯也不會死循環，請教公司大神黃炎進行一波源碼分析。

5.  semisync_master_ack_receiver.cc 的如下代碼造成了對互斥鎖的搶佔, 餓死了其餘競爭者：

void Ack_receiver::run()
{
...
while(1)
{
mysql_mutex_lock(&m_mutex);
...
select(...);
...
mysql_mutex_unlock(&m_mutex);
}
...
}

在 mysql_mutex_unlock 調用後，應適當增長其餘線程的調度機會。

試驗: 在 mysql_mutex_unlock 調用後增長 sched_yield();，可驗證問題現象消失。

 

結論

• 從庫 slave_io_thread 停滯的根本緣由是主庫對應的 dump thread 啓動不了；

• rpl_semi_sync_master_wait_for_slave_count=1 時，啓動第一個半同步後，主庫 ack_receiver 線程會不斷的循環判斷收到的 ack 數量是否 >= rpl_semi_sync_master_wait_for_slave_count，此時判斷爲 true，ack_receiver基本不會空閒一直持有鎖。此時啓動第2個半同步，對應主庫要啓動第2個 dump thread，啓動 dump thread 要等待 ack_receiver 鎖釋放，一直等不到，因此第2個 dump thread 啓動不了。

相信各位DBA同窗看了後會很震驚，「什麼？竟然還有這樣的bug...」，**這裏要說明一點，****這個bug 觸發是有概率的，可是概率又很大。**這個問題已經由我司大神提交了 bug 和 patch：https://bugs.mysql.com/bug.php?id=89370，加上本人提交SR後時不時的催一催，官方終於確認修復在 5.7.23（官方最終另有修復方法，沒采納這個 patch）。

最後或許會有疑問「既然是機率，有沒有辦法下降機率呢？」，尤爲是不具有及時升級版本條件的同窗，歡迎社區交流羣（669663113）討論~