mysql killed程序不結束_semi-sync插件崩潰導緻MySQL重新開機的故障分析-愛可生

起因：

測試公司的保障MySQL高可用元件時發現一個異常。

停止從庫，高可用元件将從庫自動啟動後，主庫發生重新開機。而正常情況下主庫不應發生重新開機。

環境：

1. OS: CentOS release 6.7 (Final)
2. MySQL：Ver 14.14 Distrib 5.7.13, for linux-glibc2.5 (x86_64) using EditLine wrapper
3. 主從執行個體開啟半同步 MySQL semi-sync配置文檔

分析：

首先，先分析log檔案

在主庫的mysql-error.log中我們可以發現如下幾點：

1. 主庫的semi-sync在崩潰前做了啟停動作。

2017-07-25T16:02:38.636061+08:00 40 [Note] Semi-sync replication switched OFF.2017-07-25T16:02:38.636105+08:00 40 [Note] Semi-sync replication disabled on the master.2017-07-25T16:02:38.636137+08:00 0 [Note] Stopping ack receiver thread2017-07-25T16:02:38.638008+08:00 40 [Note] Semi-sync replication enabled on the master.2017-07-25T16:02:38.638131+08:00 0 [Note] Starting ack receiver thread

2. 主庫的semi-sync啟動後立即引發了semi-sync插件崩潰，并抛出Assert異常。

mysqld: /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/plugin/semisync/semisync_master.cc:844: int ReplSemiSyncMaster::commitTrx(const char*, my_off_t): Assertion `entry' failed.08:02:38 UTC - mysqld got signal 6 ;

3. 這裡還有一個相當重要的複現故障的線索。簡單說明一下，這條SQL語句是為了檢測主從資料差，而由高可用中間件不斷的向資料庫更新時間戳。

Trying to get some variables.Some pointers may be invalid and cause the dump to abort.Query (7f408c0054c0): update universe.u_delay set real_timestamp=now(), logic_timestamp = logic_timestamp + 1 where source = 'ustats'Connection ID (thread ID): 61Status: NOT_KILLED

到這裡初步判斷是這個故障應與設定rpl_semi_sync_master_enabled開關相關，并且應該當時是有事務送出的。

進一步驗證，這裡隻部署一組開啟semi-sync的MySQL執行個體，而不安裝高可用元件。利用bash腳本向主庫不斷插入資料：

/opt/mysql/base/bin/mysql -uroot -p1 -S /opt/mysql/data/3306/mysqld.sock -e "create database if not exists test;use test;drop table if exists t1;create table t1(id int) "

i=0

while true

do

/opt/mysql/base/bin/mysql -uroot -p1 -S /opt/mysql/data/3306/mysqld.sock -e "insert into test.t1 values($i)"

i=$((i+1))

done

在主庫的機器上，反複運作如下指令，啟停semi-sync master，不超過5次必能複現這個故障。

/opt/mysql/base/bin/mysql -uroot -p1 -S /opt/mysql/data/3306/mysqld.sock -e'SET GLOBAL rpl_semi_sync_master_enabled = OFF;SET GLOBAL rpl_semi_sync_master_enabled = ON'

是以這個故障複現有了兩個必要條件：

1. 啟停semi-sync master
2. 資料庫當時有事務送出

其次，分析MySQL源碼

至于為什麼不能每次啟停semi-sync master都能觸發這個故障，那我們就要看看MySQL的源碼了

還好mysql-error.log明确的指出了抛出異常的位置：

mysqld: /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/plugin/semisync/semisync_master.cc:844: int ReplSemiSyncMaster::commitTrx(const char*, my_off_t): Assertion `entry' failed.08:02:38 UTC - mysqld got signal 6 ;This could be because you hit a bug. It is also possible that this binaryor one of the libraries it was linked against is corrupt, improperly built,or misconfigured. This error can also be caused by malfunctioning hardware.Attempting to collect some information that could help diagnose the problem.As this is a crash and something is definitely wrong, the informationcollection process might fail.

找到MySQL源碼，抛出異常的的位置 mysql-5.7.13 semisync_master.cc#L844

看來是這個‘entry’的值為NULL，才抛出的異常，但是這還沒有回答我的疑問。

再看MySQL的報錯資訊，MySQL自己也認識到這應該是個BUG，那它有沒有修複這個故障呢？

我找到MySQL最新5.7.19的版本，檢視它的曆史記錄mysql-5.7.19 semisync_master.cc history

這正是我想要的修複和送出，打開看看有沒有對産生故障原因的分析。Bug#22202516: ENABLING SEMI-SYNC DURING COMMIT CAN CAUSE MASTER TO ASSERT.

為了友善解釋這個BUG, 這裡先簡單的介紹一下MySQL binlog送出過程：

MySQL 在5.6版本引入了Binary Log Group Commit，二進制日志的送出由此可以簡化為三個階段：

Flush stage：将事務的日志寫入binlog檔案的緩存中

Sync stage: 将binlog檔案中的緩存資料寫入磁盤

Commit stage：根據順序調用存儲引擎送出事務。

MYSQL_BIN_LOG::ordered_commit，這個是事務在binlog階段送出的核心函數。通過該函數，實作了事務日志寫入binlog檔案，以及觸發dump線程将binlog發送到從庫，在最後将事務設定為送出狀态。

事實上，有沒有semi-sync機制，上面介紹的MySQL的有關事務送出中關于binlog的流程都是一樣的。semi-sync的作用隻是主從之間的一個确認過程，主庫等待從庫傳回相關位置的binlog已經同步到從庫的确認，沒有得到确認之前，事務送出則在該函數(步驟)上等待直至獲得傳回。

在半同步複制中，為了在主庫送出事務時等待從庫的确認，才引出了由‘entry’組成的active transaction連結清單。

在BUG分析中提到：

• 首先在flush stage，由semi-sync建立一個‘entry’，并關聯一個或一組處于flush stage的事務。這個‘entry’被插入一個active transaction連結清單。 參考: create entry

搜圖

編輯

• 接下來是sync stage，在sync stage每個處于這個階段的線程将會設定trx_wait_binlog_name和trx_wait_binlog_pos為事務對應binlog的相對位置
• 最後再commit stage，semi-sync為了等從庫的确認，會用trx_wait_binlog_name和trx_wait_binlog_pos擷取這個位置關聯的'entry', 參考: find entry

這裡有兩個場景會出現‘entry’找不到的狀況：

1. 從庫已經确認的事務在binlog位置比目前等待從庫确認的事務在binlog的位置要大

2. 當事務進入flush stage的時候semi-sync還沒有開啟，也就沒有‘entry’被建立，然後插入active transaction連結清單

這裡情況1永遠也不會進入等待階段，因為它已經被從庫确認過了。情況2則會導緻上述的斷言異常，因為這裡他無法在active transaction連結清單找到相應的’entry‘

到這裡我的疑問終于解開，原來開啟semi-sync master的時機很重要，要恰巧撞到事務送出過了flush stage但還沒有到commit stage這個縫隙。

結論：

最終修複的結果也很明顯，就是遇到找不到‘entry’，并且從庫也沒有确認的情況，這個事務送出就被認為是一次異步送出。

再看一眼在哪些版本修複了這個BUG：

是以更新MySQL版本可以解決問題。

複盤：

最後總結一下我的診斷路徑：

1. 觀察故障出現的現象，分析MySQL的error log
2. 通過猜想和實驗，構成簡單的複現場景
3. 通過日志和MySQL源碼的對應關系, 搜尋代碼曆史, 定位BUG号
4. 通過閱讀BUG的分析，了解異常發生的原理并知道了詳細的複現條件