水平有限有誤請諒解。

本文為筆者2年前寫一篇說明性文章，發(fā)現(xiàn)很多同學(xué)都在問這個(gè)問題，因此做一次分享。

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

如果要系統(tǒng)的學(xué)習(xí)主從原理可以參考我的 《深入理解MySQL主從原理 32講》。

一、延遲的計(jì)算方式

其實(shí)每次show slave status命令的時(shí)候后臺會調(diào)用函數(shù)show_slave_status_send_data進(jìn)行及時(shí)計(jì)算，這個(gè)延遲并不是保存在哪里的。棧幀如下：

#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

其計(jì)算方式基本就是這段代碼

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

稍微解釋一下：

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

這里我們也看到event中common header中的timestamp和slave本地時(shí)間起了決定因素。因?yàn)槊看伟l(fā)起命令time(0)都會增加，所以即便event中common header中的timestamp的時(shí)間不變延遲也是不斷加大的。

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

 /*
     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;
  */

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

二、Binlog寫入Binlog文件時(shí)間和event生成的時(shí)間

我發(fā)現(xiàn)有朋友這方面有疑問就做個(gè)簡單的解釋：

• binlog真正從binglog cache/tmp file寫入binlog文件是在commit的flush階段然后sync階段才落盤。
• event生成是在語句執(zhí)行期間，具體各個(gè)event生成時(shí)間如下：

1. 如果沒有顯示開啟事物，Gtid event/query event/map event/dml event/xid event均是命令發(fā)起時(shí)間。
2. 如果顯示開始事物 Gtid event/xid event是commit命令發(fā)起時(shí)間，其他event是dml語句發(fā)起時(shí)間。

所以binlog Event寫入到binlog文件和Event的中的時(shí)間沒有什么聯(lián)系。下面是一個(gè)小事物典型的event生命周期，這是工具infobin生成的：

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

三、造成延遲的可能原因

這部分是我總結(jié)現(xiàn)有的我知道的原因：

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

這些原因都是我遇到過的。接下來我想分析一下從庫system lock形成的原因。

四、問題由來

問題主要是出現(xiàn)在我們的線上庫的從庫上，我們經(jīng)常發(fā)現(xiàn)某些數(shù)據(jù)量大的數(shù)據(jù)庫，sql thread經(jīng)常處于system lock狀態(tài)下，大概表現(xiàn)如下：

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 |
+----+-------------+-----------+------+---------+------+----------------------------------+------------------+

對于這個(gè)狀態(tài)官方有如下描述:

The thread has called MySQL_lock_tables() and the thread state has not been updated since.
This is a very general state that can occur for many reasons.
For example, the thread is going to request or is waiting for an internal or external system lock for the
table. This can occur when Innodb waits for a table-level lock during execution of LOCK TABLES.
If this state is being caused by requests for external locks and you are not using multiple MySQLd
servers that are accessing the same MyISAM tables, you can disable external system locks with the
--skip-external-locking option. However, external locking is disabled by default, so it is likely
that this option will have no effect. For SHOW PROFILE, this state means the thread is requesting the
lock (not waiting for it).

顯然不能解決我的問題，一時(shí)間也是無語。而我今天在測試從庫手動加行鎖并且sql thread沖突的時(shí)候發(fā)現(xiàn)了這個(gè)狀態(tài)，因此結(jié)合gdb調(diào)試做了如下分析，希望對大家有用，也作為后期我學(xué)習(xí)的一個(gè)筆記。

五、system lock 延遲的原因

這里先直接給出原因供大家直接參考，簡單的說從庫出現(xiàn)system lock 應(yīng)該視為正在干活，而不是名稱看到的“l(fā)ock”，這是由于slave端不存在語句（row格式）的執(zhí)行，都是Event的直接apply，狀態(tài)沒有切換的機(jī)會，也可以認(rèn)為是slave端狀態(tài)劃分不嚴(yán)謹(jǐn)，其實(shí)做一個(gè)pstack就能完全看出問題。下面是產(chǎn)生的必要條件：

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

如果是大量的表沒有主鍵或者唯一鍵可以考慮修改參數(shù)slave_rows_search_algorithms 試試。關(guān)于slave_rows_search_algorithms 在我的系列中有一章詳細(xì)討論，這里不做熬述。

六、system lock 延遲的問題分析

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

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

/* Read queries from the IO/THREAD until this thread is killed */

  while (!sql_slave_killed(thd,rli)) //大循環(huán)
  {
    THD_STAGE_INFO(thd, stage_reading_event_from_the_relay_log); //這里進(jìn)入reading event from the relay log狀態(tài)
    if (exec_relay_log_event(thd,rli)) //這里會先調(diào)入next_event函數(shù)讀取一條event，然后調(diào)用lock_tables但是如果不是第一次調(diào)用lock_tables則不需要調(diào)用MySQL_lock_tables
                                       //邏輯在lock_tables調(diào)用mySQL_lock_tables則會將狀態(tài)置為system lock，然后進(jìn)入Innodb層進(jìn)行數(shù)據(jù)的查找和修改
    
  }

這里還特地請教了阿里的印風(fēng)兄驗(yàn)證了一下mysql_lock_tables是myisam實(shí)現(xiàn)表鎖的函數(shù)Innodb會設(shè)置為共享鎖。

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

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

->進(jìn)入reading event from the relay log狀態(tài) 
 ->讀取一條event(參考next_event函數(shù))
  ->進(jìn)入system lock狀態(tài)
   ->Innodb層進(jìn)行查找和修改數(shù)據(jù)

• 如果是一個(gè)大事物則包含了多條DML event的場景邏輯如下:

->進(jìn)入reading event from the relay log狀態(tài) 
 ->讀取一條event(參考next_event函數(shù))
  ->進(jìn)入system lock狀態(tài)
   ->Innodb層進(jìn)行查找和修改數(shù)據(jù)
->進(jìn)入reading event from the relay log狀態(tài) 
 ->讀取一條event(參考next_event函數(shù))
  ->Innodb層進(jìn)行查找和修改數(shù)據(jù)
->進(jìn)入reading event from the relay log狀態(tài) 
 ->讀取一條event(參考next_event函數(shù))
  ->Innodb層進(jìn)行查找和修改數(shù)據(jù)
....直到本事物event執(zhí)行完成

因此我們看到對于一個(gè)小事物我們的sql_thread會在加system lock的情況下進(jìn)行對數(shù)據(jù)進(jìn)行查找和修改，因此得出了我的結(jié)論，同時(shí)如果是Innodb 層 鎖造成的sql_thread堵塞也會在持有system lock的狀態(tài)下。但是對于一個(gè)大事物則不一樣，雖然出現(xiàn)同樣的問題，但是其狀態(tài)是reading event from the relay log。所以如果出現(xiàn)system lock一般就是考慮前文給出的結(jié)論。

七、分析中用到的斷點(diǎn)

• mysql_lock_tables 本函數(shù)更改狀態(tài)為system lock
  gdb打印:p tables[0]->s->table_name

• THD::enter_stage 本函數(shù)改變狀態(tài)
  gdb打印:p new_stage->m_name

• ha_innobase::index_read innodb查找數(shù)據(jù)接口
  gdb打印:p index->table_name

• ha_innobase::delete_row innodb刪除數(shù)據(jù)接口

• exec_relay_log_event 獲取event并且應(yīng)用
  gdb 打印:ev->get_type_code()

八、兩個(gè)棧幀

• 進(jìn)入system lock狀態(tài)

#0  THD::enter_stage (this=0x7fffec000970, new_stage=0x2ccd180, old_stage=0x0, calling_func=0x2216fd0 "mysql_lock_tables", 
    calling_file=0x22167d8 "/mysql/mysql-5.7.17/sql/lock.cc", calling_line=323) at /mysql/mysql-5.7.17/sql/sql_class.cc:731
#1  0x00000000017451a6 in mysql_lock_tables (thd=0x7fffec000970, tables=0x7fffec005e38, count=1, flags=0) at /mysql/mysql-5.7.17/sql/lock.cc:323
#2  0x00000000014fe8da in lock_tables (thd=0x7fffec000970, tables=0x7fffec012b70, count=1, flags=0) at /mysql/mysql-5.7.17/sql/sql_base.cc:6630
#3  0x00000000014fe321 in open_and_lock_tables (thd=0x7fffec000970, tables=0x7fffec012b70, flags=0, prelocking_strategy=0x7ffff14e2360)
    at /mysql/mysql-5.7.17/sql/sql_base.cc:6448
#4  0x0000000000eee1d2 in open_and_lock_tables (thd=0x7fffec000970, tables=0x7fffec012b70, flags=0) at /mysql/mysql-5.7.17/sql/sql_base.h:477
#5  0x000000000180e7c5 in Rows_log_event::do_apply_event (this=0x7fffec024790, rli=0x393b9c0) at /mysql/mysql-5.7.17/sql/log_event.cc:10626
#6  0x00000000017f7b7b in Log_event::apply_event (this=0x7fffec024790, rli=0x393b9c0) at /mysql/mysql-5.7.17/sql/log_event.cc:3324
#7  0x00000000018690ff in apply_event_and_update_pos (ptr_ev=0x7ffff14e2818, thd=0x7fffec000970, rli=0x393b9c0) at /mysql/mysql-5.7.17/sql/rpl_slave.cc:4709
#8  0x000000000186a7f2 in exec_relay_log_event (thd=0x7fffec000970, rli=0x393b9c0) at /mysql/mysql-5.7.17/sql/rpl_slave.cc:5224//這里可以看到不同event不同的處理
#9  0x0000000001870db6 in handle_slave_sql (arg=0x357fc50) at /mysql/mysql-5.7.17/sql/rpl_slave.cc:7332//這里是整個(gè)主邏輯
#10 0x0000000001d5442c in pfs_spawn_thread (arg=0x7fffd88fb870) at /mysql/mysql-5.7.17/storage/perfschema/pfs.cc:2188
#11 0x00007ffff7bc7851 in start_thread () from /lib64/libpthread.so.0
#12 0x00007ffff672890d in clone () from /lib64/libc.so.6

• 在system lock狀態(tài)下查找數(shù)據(jù)

#0  ha_innobase::index_read (this=0x7fffec0294c0, buf=0x7fffec0297b0 "\375\311y", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY)
    at /mysql/mysql-5.7.17/storage/innobase/handler/ha_innodb.cc:8540
#1  0x000000000192126c in ha_innobase::index_first (this=0x7fffec0294c0, buf=0x7fffec0297b0 "\375\311y")
    at /mysql/mysql-5.7.17/storage/innobase/handler/ha_innodb.cc:9051
#2  0x00000000019214ba in ha_innobase::rnd_next (this=0x7fffec0294c0, buf=0x7fffec0297b0 "\375\311y") at /mysql/mysql-5.7.17/storage/innobase/handler/ha_innodb.cc:9149
#3  0x0000000000f4972c in handler::ha_rnd_next (this=0x7fffec0294c0, buf=0x7fffec0297b0 "\375\311y") at /mysql/mysql-5.7.17/sql/handler.cc:2947
#4  0x000000000180e1a9 in Rows_log_event::do_table_scan_and_update (this=0x7fffec035c20, rli=0x393b9c0) at /mysql/mysql-5.7.17/sql/log_event.cc:10475
#5  0x000000000180f453 in Rows_log_event::do_apply_event (this=0x7fffec035c20, rli=0x393b9c0) at /mysql/mysql-5.7.17/sql/log_event.cc:10941
#6  0x00000000017f7b7b in Log_event::apply_event (this=0x7fffec035c20, rli=0x393b9c0) at /mysql/mysql-5.7.17/sql/log_event.cc:3324
#7  0x00000000018690ff in apply_event_and_update_pos (ptr_ev=0x7ffff14e2818, thd=0x7fffec000970, rli=0x393b9c0) at /mysql/mysql-5.7.17/sql/rpl_slave.cc:4709
#8  0x000000000186a7f2 in exec_relay_log_event (thd=0x7fffec000970, rli=0x393b9c0) at /mysql/mysql-5.7.17/sql/rpl_slave.cc:5224
#9  0x0000000001870db6 in handle_slave_sql (arg=0x357fc50) at /mysql/mysql-5.7.17/sql/rpl_slave.cc:7332
#10 0x0000000001d5442c in pfs_spawn_thread (arg=0x7fffd88fb870) at /mysql/mysql-5.7.17/storage/perfschema/pfs.cc:2188
#11 0x00007ffff7bc7851 in start_thread () from /lib64/libpthread.so.0
#12 0x00007ffff672890d in clone () from /lib64/libc.so.6

九、相關(guān)測試

下面來測試一下system lock這種狀態(tài)，使用一張包含5條數(shù)據(jù)的表，表結(jié)構(gòu)如下：

root@localhost:testrep:04:29:18>select count(*) from testrep;
+----------+
| count(*) |
+----------+
|        5 |
+----------+
1 row in set (0.00 sec)
root@localhost:testrep:04:30:12>show create table testrep
    -> ;
+---------+------------------------------------------------------------------------------------------------------------------------------------+
| Table   | Create Table                                                                                                                       |
+---------+------------------------------------------------------------------------------------------------------------------------------------+
| testrep | CREATE TABLE `testrep` (
  `id` int(11) NOT NULL,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin |
+---------+------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

1 從庫開啟事務(wù)，同時(shí)鎖住一行數(shù)據(jù)，如下：
begin;select *from testrep where id=5 for update;
2 主庫執(zhí)行刪除語句，刪除這5行數(shù)據(jù)，如下：
delete from testrep;
3 從庫進(jìn)行觀察可以發(fā)現(xiàn)system lock狀態(tài)

root@localhost:testrep:04:35:14>select state  from information_schema.processlist where id=9;
+-------------+
| state       |
+-------------+
| System lock |
+-------------+
1 row in set (0.00 sec)

出現(xiàn)的原因就是主庫刪除的5條數(shù)據(jù)會處于一個(gè)DELETE_EVENT中，我們現(xiàn)在知道了一個(gè)Event最大為8K左右，因此本事務(wù)只包含了一個(gè)Event。從庫由于id=5的這條數(shù)據(jù)上了Innodb 行鎖，因此SQL線程不能對這條數(shù)據(jù)進(jìn)行處理，導(dǎo)致了system lock的出現(xiàn)。