從Mysql slave system lock延遲說開去

風塵_NULL發表於2018-04-12
MySql

本文主要分析 sql thread中system lock出現的原因，但是筆者並明沒有系統的學習過master-slave的程式碼，這也是2018年的一個目標，2018年我都排滿了，悲劇。所以如果有錯誤請指出，也作為一個筆記用於後期學習。同時也給出筆者現在知道的幾種造成延遲的可能和延遲計算的方式。

  • 本文基於5.7.17原始碼
  • 本文只考慮row 格式binlog
  • 主要考慮DML語句，DDL語句比較簡單不做考慮

一、延遲的計算方式

其實每次show slave status命令的時候後臺會呼叫函式show_slave_status_send_data進行及時計算，這個延遲並不是儲存在哪裡的。棧幀如下： 

#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

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

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

稍微解釋一下：

  • 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的時間不變延遲也是不斷加大的。

另外還有一段有名的虛擬碼如下： 

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

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

這部分還可以參考一下淘寶核心月報

二、Binlog寫入Binlog檔案時間和event生成的時間

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

  • binlog真正寫入binlog檔案是在commit後，傳輸是在order commit的flush後。
  • event生成的時間：
  1. 如果沒有顯示開啟事物，Gtid event/query event/map event/dml event/xid event均是命令發起時間
  2. 如果顯示開始事物 Gtid event/xid event是commit命令發起時間，其他event是dml語句發起時間

當然binlog寫入到binlog檔案或者什麼時候傳輸到slave和event的生成沒有什麼聯絡。
下面是一個小事物典型的event生命週期 

>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

三、造成延遲的可能原因

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

  • 大事物延遲 延遲略為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狀態下，大概表現如下： 

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

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

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).

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

五、system lock 延遲的原因

這裡直接給出原因供大家直接參考:
必要條件：
由於大量的小事物如UPDATE/DELETE table where一行資料，這種只包含一行DML event的語句，table是一張大表。

  • 這個表上沒有主鍵或者唯一鍵。
  • 由於類似innodb lock堵塞，也就是slave從庫修改了資料同時和sql_thread也在修改同樣的資料。
  • 確實I/O扛不住了，可以嘗試修改引數。

如果是大量的表沒有主鍵或者唯一鍵可以考慮修改引數slave_rows_search_algorithms 試試。但是innodb中不用主鍵或者主鍵不選擇好就等於自殺。

六、system lock 延遲的問題分析

下面的分析是我通過gdb程式碼得出的結論可能有誤
我們知道所有的state都是mysql上層的一種狀態，如果要發生狀態的改變必須要呼叫THD::enter_stage來改變，而system lock則是呼叫mysql_lock_tables進入的狀態，同時從庫SQL_THREAD中還有另外一種狀態重要的狀態reading event from the relay log。

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

/* 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層進行資料的查詢和修改 }

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

這裡我們先拋開query event/map event等。只考慮DML event

  • 如果一個小事物只有一條DML event的場景下邏輯如下： 
->進入reading event from the relay log狀態 
 ->讀取一條event(參考next_event函式)
  ->進入system lock狀態
   ->innodb層進行查詢和修改資料
  • 如果是一個大事物則包含了多條DML event的場景邏輯如下: 
->進入reading event from the relay log狀態 
 ->讀取一條event(參考next_event函式)
  ->進入system lock狀態
   ->innodb層進行查詢和修改資料
->進入reading event from the relay log狀態 
 ->讀取一條event(參考next_event函式)
  ->innodb層進行查詢和修改資料
->進入reading event from the relay log狀態 
 ->讀取一條event(參考next_event函式)
  ->innodb層進行查詢和修改資料
....直到本事物event執行完成

因此我們看到對於一個小事物我們的sql_thread會在加system lock的情況下進行對資料進行查詢和修改，因此得出了我的結論，同時如果是innodb 層 鎖造成的sql_thread堵塞也會在持有system lock的狀態下。但是對於一個大事物則不一樣，雖然出現同樣的問題的但是其狀態是reading event from the relay log。所以如果出現system lock一般就是考慮前文給出的結論，但是前文給出的結論不一定都會引起system lock，這個要看是否是大事物。

以下的部分是我進行gdb的時候用到斷點和棧幀是我自己看的

七、分析中用到的斷點

  • 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()

八、兩個棧幀

  • 進入system lock狀態 
#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//這裡是整個主邏輯 #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狀態下查詢資料 
#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

作者微信：


從Mysql slave system lock延遲說開去
微信.jpg

來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/7728585/viewspace-2149659/，如需轉載，請註明出處，否則將追究法律責任。

相關文章