文章末尾有他著作的《深入理解 MySQL 主從原理 32 講》，深入透徹理解 MySQL 主從，GTID 相關技術知識。

本文為筆者 2 年前寫一篇說明性文章，發現很多同學都在問這個問題，因此做一次分享。

• 本文基於 5.7.17 源碼
• 本文只考慮 row 格式 binlog
• 主要考慮 DML 語句，DDL 語句比較簡單不做考慮
• 以單 sql 線程為例（非 MTS）

如果要系統的學習主從原理可以參考我的 《深入理解 MySQL 主從原理 32 講》。

一、延遲的計算方式

其實每次 show slave status 命令的時候後臺會調用函數 show_slave_status_send​_data 進行及時計算，這個延遲並不是保存在哪裡的。棧幀如下：

<code>#0  show_slave_status_send_data (thd=0x7fffd8000cd0, mi=0x38ce2e0, io_gtid_set_buffer=0x7fffd800eda0 "e859a28b-b66d-11e7-8371-000c291f347d:42-100173",    sql_gtid_set_buffer=0x7fffd8011ac0"e859a28b-b66d-11e7-8371-000c291f347d:1-100173") at /MySQL/MySQL-5.7.17/sql/rpl_slave.cc:3602#1  0x0000000001867749 in show_slave_status (thd=0x7fffd8000cd0) at /MySQL/MySQL-5.7.17/sql/rpl_slave.cc:3982#2  0x0000000001867bfa in show_slave_status_cmd (thd=0x7fffd8000cd0) at /MySQL/MySQL-5.7.17/sql/rpl_slave.cc:4102/<code>

其計算方式基本就是這段代碼，

<code>time_diff= ((long)(time(0) - mi->rli->last_master_timestamp) - mi->clock_diff_with_master);/<code>

稍微解釋一下：

• time(0) ：取當前 slave 服務器系統時間。
• mi->rli->last_master_timestamp：是 event common header 中 timestamp 的時間 + exetime，其中 exetime 只有 query event 才有，其他全部是 0，這也導致了 binlog row 格式下的延遲最大基本是（2 乘以主庫的執行的時間），但是 DDL 的語句包含在 query event 中索引延遲最大基本就是（1 乘以主庫執行時間）
• mi->clock_diff_with_master：這是從庫和主庫時間的差值。

這裡我們也看到 event 中 common header 中的 timestamp 和 slave 本地時間起了決定因素。因為每次發起命令 time(0) 都會增加，所以即便 event 中 common header 中的 timestamp 的時間不變延遲也是不斷加大的。

另外還有一段有名的偽代碼如下：

<code>/*     The pseudo code to compute Seconds_Behind_Master:     if (SQL thread is running)     {       if (SQL thread processed all the available relay log)       {         if (IO thread is running)            print 0;         else            print NULL;       }        else          compute Seconds_Behind_Master;      }      else       print NULL;  *//<code>

其實他也來自函數 show_slave_status_send_data，有興趣的自己在看看，我就不過多解釋了。

二、Binlog 寫入 Binlog 文件時間和 event 生成的時間

我發現有朋友這方面有疑問就做個簡單的解釋：

• binlog 真正從 binglog cache/tmp file 寫入 binlog 文件是在 commit 的 flush 階段然後 sync 階段才落盤。
• event 生成是在語句執行期間，具體各個 event 生成時間如下：1）如果沒有顯示開啟事物，Gtid event/query event/map event/dml event/xid event 均是命令發起時間。2）如果顯示開始事物 Gtid event/xid event 是 commit 命令發起時間，其他 event 是 dml 語句發起時間。

所以 binlog Event 寫入到 binlog 文件和 Event 的中的時間沒有什麼聯繫。下面是一個小事物典型的 event 生命週期，這是工具 infobin 生成的：

<code>>GtidEvent:Pos:234(0Xea) N_pos:299(0X12b) Time:1513135186Event_size:65(bytes)Gtid:31704d8a-da74-11e7-b6bf-52540a7d243:100009 last_committed=0  sequence_number=1-->QueryEvent:Pos:299(0X12b) N_Pos:371(0X173) Time:1513135186Event_size:72(bytes)Exe_time:0Use_db:test Statment(35b-trun):BEGIN/*!Trx begin!*/Gno:100009---->MapEvent:Pos371(0X173) N_pos:415(0X19f) Time:1513135186Event_size:44(bytes)TABLE_ID:108 DB_NAME:test TABLE_NAME:a Gno:100009------>InsertEvent:Pos:415(0X19f) N_pos:455(0X1c7) Time:1513135186Event_size:40(bytes)Dml on table: test.a  table_id:108Gno:100009>XidEvent:Pos:455(0X1c7) N_Pos:486(0X1e6) Time:1513135186Event_size:31(bytes)COMMIT; /*!Trx end*/Gno:100009/<code>

三、造成延遲的可能原因

這部分是我總結現有的我知道的原因：

• 大事物延遲，延遲略為 2 執行時間，狀態為：reading event from the relay log
• 大表 DDL 延遲，延遲略為 1 執行時間，狀態為：altering table
• 長期未提交的事物延遲，會造成延遲的瞬時增加
• 表上沒有主鍵或者唯一鍵，狀態為：system lock 或者 reading event from the relay log
• Innodb 層鎖造成延遲，狀態為：system lock 或者 reading event from the relay log
• 從庫參數設置如 sync_binlog，sync_relay_log，Innodb_flush_log_at_trx_commit 等參數

這些原因都是我遇到過的。

接下來我想分析一下從庫 system lock 形成的原因。

四、問題由來

問題主要是出現在我們的線上庫的從庫上，我們經常發現某些數據量大的數據庫，sql thread經常處於 system lock 狀態下，大概表現如下：

<code>MySQL> show processlist;+----+-------------+-----------+------+---------+------+----------------------------------+------------------+| Id | User        | Host      | db   | Command | Time | State                            | Info             |+----+-------------+-----------+------+---------+------+----------------------------------+------------------+|  3 | root        | localhost | test | Sleep   |  426 |                                  | NULL             ||  4 | system user |           | NULL | Connect | 5492 | Waiting for master to send event | NULL             ||  5 | system user |           | NULL | Connect |  104 | System lock                      | NULL             |                       ||  6 | root        | localhost | test | Query   |    0 | starting                         | show processlist |+----+-------------+-----------+------+---------+------+----------------------------------+------------------+/<code>

對於這個狀態官方有如下描述：

<code>The thread has called MySQL_lock_tables() and the thread state has not been updated since.Thisis a very general state that can occur for many reasons.For example, the thread is going to request oris waiting for an internalor external system lockfor thetable. This can occur whenInnodb waits for a table-level lock during execution of LOCK TABLES.Ifthis state is being caused by requests for external locks and you are notusing multiple MySQLdservers that are accessing the same MyISAM tables, you can disable external system locks with the--skip-external-locking option. However, external locking is disabled bydefault, so it is likelythat this option will have no effect. For SHOW PROFILE, this state means the thread is requesting thelock(not waiting for it)./<code>

顯然不能解決我的問題，一時間也是無語。而我今天在測試從庫手動加行鎖並且 sql thread 衝突的時候發現了這個狀態，因此結合 gdb 調試做了如下分析，希望對大家有用，也作為後期我學習的一個筆記。

五、system lock 延遲的原因

這裡先直接給出原因供大家直接參考，簡單的說從庫出現 system lock 應該視為正在幹活，而不是名稱看到的“lock”，這是由於 slave 端不存在語句（row 格式）的執行，都是 Event 的直接 apply，狀態沒有切換的機會，也可以認為是 slave 端狀態劃分不嚴謹，其實做一個 pstack 就能完全看出問題。下面是產生的必要條件：

• 由於大量的小事物，比如 UPDATE/DELETE table where 處理一行數據，這會出現只包含一行數據庫的 DML event 的語句，如果 table 是一張大表，則會加劇這種可能。
• 這個表上沒有主鍵或者唯一鍵，問題加劇。
• 由於類似 Innodb lock 堵塞，也就是 slave 從庫修改了數據同時和 sql_thread 也在修改同樣的數據，問題加劇。
• 確實 I/O 扛不住了，可以嘗試修改參數。

如果是大量的表沒有主鍵或者唯一鍵可以考慮修改參數 slave_rows_search_algorithms 試試。關於 slave_rows_search_algorithms 在我的系列中有一章詳細討論，這裡不做贅述。

六、system lock 延遲的問題分析

我們知道所有的 state 都是 MySQL 上層的一種狀態，如果要發生狀態的改變必須要調用 THD::enter_stage 來改變，而 system lock 則是調用 mysql_lock_tables 進入的狀態，同時從庫 SQL_THREAD 中還有另外一種狀態重要的狀態 reading event from the relay log。

這裡是 rpl_slave.cc handle_slave_sql 函數中的很小的一部分主要用來證明我的分析。

<code>/* Read queries from the IO/THREAD until this thread is killed */while(!sql_slave_killed(thd,rli)) //大循環{    THD_STAGE_INFO(thd, stage_reading_event_from_the_relay_log); //這裡進入reading event from the relay log狀態if(exec_relay_log_event(thd,rli)) //這裡會先調入next_event函數讀取一條event，然後調用lock_tables但是如果不是第一次調用lock_tables則不需要調用MySQL_lock_tables//邏輯在lock_tables調用mySQL_lock_tables則會將狀態置為system lock，然後進入Innodb層進行數據的查找和修改}/<code> 

這裡還特地請教了阿里的印風兄驗證了一下 mysql_lock_tables 是 myisam 實現表鎖的函數 Innodb 會設置為共享鎖。

這裡我們先拋開 query event/map event 等。只考慮 DML event，下面就是 system lock 出現的流程：

• 如果一個小事物只有一條 DML event 的場景下邏輯如下：

<code>->進入reading eventfrom the relay log狀態 ->讀取一條event(參考next_event函數)  ->進入system lock狀態   ->Innodb層進行查找和修改數據/<code>

• 如果是一個大事物則包含了多條 DML event 的場景邏輯如下：

<code>->進入reading eventfrom the relay log狀態 ->讀取一條event(參考next_event函數)  ->進入system lock狀態   ->Innodb層進行查找和修改數據->進入reading eventfrom the relay log狀態 ->讀取一條event(參考next_event函數)  ->Innodb層進行查找和修改數據->進入reading eventfrom the relay log狀態 ->讀取一條event(參考next_event函數)  ->Innodb層進行查找和修改數據....直到本事物event執行完成/<code>

因此我們看到對於一個小事物我們的 sql_thread 會在加 system lock 的情況下進行對數據進行查找和修改。

因此得出了我的結論，同時如果是 Innodb 層鎖造成的 sqlthread 堵塞也會在持有 system lock 的狀態下。但是對於一個大事物則不一樣，雖然出現同樣的問題，但是其狀態是 reading event from the relay log。

所以如果出現 system lock 一般就是考慮前文給出的結論。

七、分析中用到的斷點

• mysql_lock_tables 本函數更改狀態為 system lock gdb 打印 :p tables[0]->s->table_name
• THD::enter_stage 本函數改變狀態 gdb 打印 :p new_stage->m_name
• ha_innobase::index_read innodb 查找數據接口 gdb 打印 :p index->table_name
• ha_innobase::delete_row innodb 刪除數據接口
• exec_relay_log_event 獲取 event 並且應用 gdb 打印 :ev->get_type_code()

最後推薦高鵬的專欄《深入理解 MySQL 主從原理 32 講》，想要透徹瞭解學習 MySQL 主從原理的朋友不容錯過。

閱讀更多 愛可生 的文章

關鍵字: MySQL 從庫 技術