天天看點

記一次不常見到主從延遲問題

一、問題:發現RDS執行個體主從資料不一緻

二、分析:可能的原因

1.主從複制中斷

2.主從延遲(DDL語句,大事務,隻讀執行個體負載高等)

3.實時性查詢高

4.丢資料(binlog row格式可能性很小)

三、排查:

擷取隻讀執行個體的複制狀态,show slave status

\

G:

1. row **

Slave_IO_State: Waiting for master to send event
              Master_Host: XXXXXXX
              Master_User: replicator
              Master_Port: XXXX
            Connect_Retry: 60
          Master_Log_File: mysql-bin.001798
      Read_Master_Log_Pos: 15683249
           Relay_Log_File: slave-relay.002090
            Relay_Log_Pos: 88207647
    Relay_Master_Log_File: mysql-bin.001797
         Slave_IO_Running: Yes
        Slave_SQL_Running: Yes
          Replicate_Do_DB: 
      Replicate_Ignore_DB: 
       Replicate_Do_Table: 
   Replicate_Ignore_Table: 
  Replicate_Wild_Do_Table:            

Replicate_Wild_Ignore_Table:

Last_Errno: 0
               Last_Error: 
             Skip_Counter: 0
      Exec_Master_Log_Pos: 128759954
          Relay_Log_Space: 147040856
          Until_Condition: None
           Until_Log_File: 
            Until_Log_Pos: 0
       Master_SSL_Allowed: No
       Master_SSL_CA_File: 
       Master_SSL_CA_Path: 
          Master_SSL_Cert: 
        Master_SSL_Cipher: 
           Master_SSL_Key: 
    Seconds_Behind_Master: 9366           

Master_SSL_Verify_Server_Cert: No

Last_IO_Errno: 0
            Last_IO_Error: 
           Last_SQL_Errno: 0
           Last_SQL_Error:            

Replicate_Ignore_Server_Ids:

Master_Server_Id: XXXX
              Master_UUID: XXXX
         Master_Info_File: mysql.slave_master_info
                SQL_Delay: 0
      SQL_Remaining_Delay: 
  Slave_SQL_Running_State: Waiting for dependent transaction to commit
       Master_Retry_Count: 86400
              Master_Bind: 
  Last_IO_Error_Timestamp: 
 Last_SQL_Error_Timestamp: 
      Last_SQL_Error_Gtid: 
           Master_SSL_Crl: 
       Master_SSL_Crlpath: 
       Retrieved_Gtid_Set: 64f5764b-abfd-11e8-b97f-6c92bf4645d4:6903-76788620
        Executed_Gtid_Set: 64f5764b-abfd-11e8-b97f-6c92bf4645d4:1-76781839,           

73e54b6b-abfd-11e8-9bb5-6c92bf3a3bee:1-131695420

Auto_Position: 1
     Replicate_Rewrite_DB: 
             Channel_Name: 
       Master_TLS_Version: 
           

解讀下:看到IO Thread和SQL Thread線程正常都是YES 複制正常。

Seconds_Behind_Master: 9366, Relay_Master_Log_File: mysql-bin.001797 和 Master_Log_File: mysql-bin.001798 可以判斷主從複制相差一個binlog日志有延遲,延遲時間大概9366秒。

繼續分析隻讀執行個體負載不高

記一次不常見到主從延遲問題
記一次不常見到主從延遲問題

慢日志裡有delete操作,但執行時間不是特别長,可以先忽略。

show processlist 也并未發現DDL語句執行

記一次不常見到主從延遲問題

繼續看複制資訊 Slave_SQL_Running_State: Waiting for dependent transaction to commit 等待依賴的事務送出,這裡提醒了我們relay log在回放某個event的時候,在等待某個事務送出。是以查詢下infomation_schema.innodb_trx 這個系統表,裡面會記錄未送出事務執行資訊

記一次不常見到主從延遲問題
記一次不常見到主從延遲問題

從結果看确實有2個未送出事務已經跑了很久了,為了盡快解決生産問題,建議客戶kill 掉了這2個sql,這裡說下trx_mysql_thread_id 對應的是processlist表裡的id,是以kill時候,可以kill trx_mysql_thread_id。

結果:kill掉這2個未送出事務之後,延遲恢複。

四.複現客戶問題

觀察到當時SQL線程回放event時候,在等待table flush

記一次不常見到主從延遲問題

資料:

FLUSH TABLES

Closes all open tables, forces all tables in use to be closed, and flushes the query cache and prepared statement cache. FLUSH TABLES also removes all query results from the query cache, like the RESET QUERY CACHE statement. For information about query caching and prepared statement caching, see Section 8.10.3, “The MySQL Query Cache”. and Section 8.10.4, “Caching of Prepared Statements and Stored Programs”.

mysql官網說明:

https://dev.mysql.com/doc/refman/5.6/en/flush.html#flush-tables

說明下,flush tables遇到前面有大事務執行不完,還會産生阻塞,線程狀态就是waiting for table flush(阻塞僅限于該表)

基于這些資訊我們還原下問題

4.1先在隻讀執行個體,開啟一個性能差的大查詢事務,SQL一直執行不完

記一次不常見到主從延遲問題

4.2在隻讀執行個體另外開啟一個會話執行flush tables tablename

記一次不常見到主從延遲問題

4.3主執行個體插入一條測試資料

記一次不常見到主從延遲問題

4.4查詢隻讀執行個體的sql線程,可以看到SQL線程的狀态waiting for table flush,第一個查詢一值執行不完不送出,

第二步flush tables tablename就阻塞了第三步的sql

記一次不常見到主從延遲問題

4.5查詢隻讀執行個體的複制狀态,同樣可以看到:Waiting for dependent transaction to commit

記一次不常見到主從延遲問題

4.6同樣也可以查到未送出的這個大事務

記一次不常見到主從延遲問題

總結:未送出事務和flush tables導緻relay log回放event時候,産生了阻塞,複制不能繼續,産生主從延遲

客戶的問題還可以通過解析binlog定位到當時relay log 回放到binlog的event了,可以佐證該事務在等待這2個事務commit或rollback。解析時候分析這個位置Relay_Master_Log_File: mysql-bin.001797,Exec_Master_Log_Pos: 128759954,row格式使用指令:mysqlbinlog -vv --base64-output=decode-rows --start-position=128759954 mysql-bin.001797 | less