揭祕MySQL 主從環境中大事務的傳奇事蹟

沃趣科技發表於2019-10-07
MySql


toc

  • 或許某些人會說MySQL Low，而且樂此不疲，不過，我完全也可以說某些人壓根就不會用MySQL，萬事萬物都具有兩面性的，最終結果的好壞還得看是誰在用、怎麼用。關於這個問題的爭論，相信大家都喜聞樂見了，尤其是資料庫界的"郭德綱"的言論尤其精彩，沒事聽聽資料庫界的"郭德綱"講講故事、講講段子，也是一件蠻有意思的事情。
  • 說回到大事務，大家或多或少都不太喜歡它，在日常的工作中，或許會在開發規範裡明令禁止大事務（運算元據行數過萬的事務可以毛估估的算作是大事務），也或許會在開發規範裡建議程式設計師們儘可能將大事務拆分為小事務，即便特殊情況不得不跑大事務，至少也要在會話級別將binlog格式改成statement。大事務對資料庫的影響，相信各位都或多或少有些體會。我就不一一列舉，在這裡，我想說的是，既然大家都覺得跑大事務不好，那大事務在MySQL裡跑起來到底長啥樣呢？下面我們圍繞這個話題，針對"在MySQL主從複製環境中跑一個大事務"的場景，剖析一下大事務在MySQL中的"傳奇事蹟"

1、環境資訊

  • 資料庫版本：MySQL 5.7.27
  • 資料庫關鍵配置引數：
    • 主從庫：雙一、long_query_time=1、binlog_rows_query_log_events=ON、binlog_format=row、slow_query_log=ON、innodb_buffer_pool_size=10G、max_binlog_size=512M
    • 從庫：雙TABLE、log_slow_slave_statements=ON、slave_parallel_type=LOGICAL_CLOCK、slave_parallel_workers=16、slave_preserve_commit_order=ON、slave_rows_search_algorithms='INDEX_SCAN,HASH_SCAN'、log_slave_updates=ON
  • 主從複製拓撲
    • 主庫：10.10.30.162
    • 從庫：10.10.30.163
  • 伺服器硬體配置（kvm）
    • CPU：8 vcpus
    • 記憶體：16G
    • 磁碟：100G（LSI 1.6T FLASH卡）
  • 其他工具版本
    • sysbench：sysbench 1.0.9
    • percona-toolkit：percona-toolkit-3.0.13-1.el7.x86_64

2、環境準備

  • 主從庫都啟用所有的等待事件（這裡使用了sys schema下的儲存過程ps_setup_enable_instrument和ps_setup_enable_consumer進行快捷操作，代替使用UPDATE語句直接修改performance_schema系統庫下的setup_instruments和setup_consumers表）

mysql > call sys.ps_setup_enable_instrument('wait');
+-------------------------+
| summary |
+-------------------------+
| Enabled 310 instruments |
+-------------------------+
1 row in set (0.01 sec)
Query OK, 0 rows affected (0.01 sec)
mysql > call sys.ps_setup_enable_consumer('wait');          
+---------------------+
| summary |
+---------------------+
| Enabled 3 consumers |
+---------------------+
1 row in set (0.00 sec)

  • 主庫造數2張1000W的表

# 造數命令
[root@physical-machine ~]# sysbench --db-driver=mysql --time=99999 --threads=2 --report-interval=1 --mysql-host=10.10.30.162 --mysql-port=3306 --mysql-user=qbench --mysql-password=qbench --mysql-db=sbtest --tables=2 --table-size=10000000 oltp_read_write --db-ps-mode=disable prepare
# 表結構
CREATE TABLE `sbtest1` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `k` int(11) NOT NULL DEFAULT '0',
  `c` char(120) COLLATE utf8_bin NOT NULL DEFAULT '',
  `pad` varchar(70) COLLATE utf8_bin NOT NULL DEFAULT '',
  PRIMARY KEY (`id`),
  KEY `k_1` (`k`)
) ENGINE=InnoDB AUTO_INCREMENT=20000001 DEFAULT CHARSET=utf8 COLLATE=utf8_bin  # 這裡AUTO_INCREMENT=20000001是因為自增步長引數設定為了2，實際上資料只插入了1000W行

  • 主庫造數完成之後，檢視從庫複製狀態，確認從庫複製無延遲

mysql > show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 10.10.30.162
                  Master_User: repl
                  Master_Port: 3306
                Connect_Retry: 10
              Master_Log_File: mysql-bin.000015
          Read_Master_Log_Pos: 215657137
               Relay_Log_File: mysql-relay-bin.000044
                Relay_Log_Pos: 215657350
        Relay_Master_Log_File: mysql-bin.000015
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
......
          Exec_Master_Log_Pos: 215657137
              Relay_Log_Space: 215657644
......
        Seconds_Behind_Master: 0
......
           Retrieved_Gtid_Set: 6f43ada4-d39d-11e9-9c97-5254002a54f2:1-7485
            Executed_Gtid_Set: 6f43ada4-d39d-11e9-9c97-5254002a54f2:1-7485
                Auto_Position: 1
         Replicate_Rewrite_DB: 
                 Channel_Name: 
           Master_TLS_Version: 
1 row in set (0.00 sec)
# 從上述內容中，我們可以通過兩種方式判斷是否存在複製延遲（僅從SQL執行緒追趕IO執行緒的角度衡量，如果是IO執行緒讀取的binlog日誌本身與主庫存在延遲，在從庫側無法判斷，需要結合主從的實際情況進行判斷）
## 方法一：比對二進位制日誌檔案和位置資訊，Master_Log_File = Relay_Master_Log_File && Read_Master_Log_Pos = Exec_Master_Log_Pos，如果它們完全相等，則說明從庫側無複製延遲
## 方法二：比對GTID SET資訊，Retrieved_Gtid_Set = Executed_Gtid_Set，如果它們完全相等，則說明從庫側無複製延遲

  • 主從庫各自清理performance_schema統計資料，並切換binlog，避免對後續的操作過程造成干擾

# 清理ps統計資料（sys.ps_truncate_all_tables()函式的作用：清空performance_schema下的%summary%和%history%表，有一個傳參，表示是否在每一張表執行清空前列印表名，如果為FALSE，則不列印， 只在執行操作完成最後列印總操作表數量）
mysql > CALL sys.ps_truncate_all_tables(false);
+---------------------+
| summary |
+---------------------+
| Truncated 44 tables |
+---------------------+
1 row in set (0.09 sec)
Query OK, 0 rows affected (0.09 sec)
# 切換binlog
mysql > flush binary logs;
Query OK, 0 rows affected (0.02 sec)

  • 主從庫分別執行一個加壓輔助指令碼，主庫並行執行2個UPDATE語句（分別對sbtest1和sbtest2表發起UPDATE操作），從庫並行執行2個SELECT語句（分別對sbtest1和sbtest2表發起SELECT操作）（指令碼程式碼詳見文末的下載連結）

# 主庫（該指令碼會按照指定的時間間隔迴圈檢查執行時長超過該指定間隔時間的會話狀態，如果存在超時的會話，則嘗試使用show processlist語句、sys.session檢視列印更加詳細的會話資訊，並嘗試使用sys.innodb_lock_waits檢視列印鎖等待資訊；如果不存在超時會話，則並行使用2個會話對指定的表執行UPDATE語句，注意：指令碼中的兩個UPDATE語句的id取值為id列的一個較小值，不要與後續需要執行的大事務中的id值範圍有鎖衝突）
[root@physical-machine ~]# sh exec_parallel_sql_master.sh 
## 指令碼執行過程中，會按照指定的時間間隔列印一些執行日誌，每列印一次就表示UPDATE語句執行成功了一次
now() mark
2019-09-11 13:40:36 ------------------
now() mark
2019-09-11 13:40:37 ------------------
now() mark
2019-09-11 13:40:37 ------------------
......
# 從庫（與主庫中的exec_parallel_sql_master.sh指令碼作用類似，但在從庫中，不存在超時會話時，並行執行的語句從UPDATE改為SELECT）
[root@node2 ~]# sh exec_parallel_sql_slave.sh 
## 指令碼執行過程中，會按照指定的時間間隔列印一些執行日誌，以及SELECT語句的查詢結果
2019-09-11 13:40:54 ------------------
id k c pad
1000001 4982373 33215995692-11643009243-86512240766-52474552185-05677806687-01251571470-76461373271-04600478707-30936631606-18731704317 91106890267-89662465049-88180742274-99973317521-51514147703
now() mark
2019-09-11 13:40:55 ------------------
id k c pad
2000001 4979176 84112274222-72580329847-55073805313-86104475687-27118798543-60440415134-55566695297-03778364972-89646151895-46966443039 40891678273-04756075401-41893687834-80508607710-52345565443
now() mark
2019-09-11 13:40:55 ------------------
......

  • 另起一個ssh終端會話，在從庫執行一個每秒查詢複製延遲的指令碼（指令碼程式碼詳見文末的下載連結）

[root@node2 ~]# sh check_slave_delay.sh 
# 指令碼執行過程中，會按照指定的時間間隔列印一些執行日誌
當前備庫複製延遲(intervel=1,2019-09-11_13:41:31): 0
當前備庫複製延遲(intervel=1,2019-09-11_13:41:32): 0
當前備庫複製延遲(intervel=1,2019-09-11_13:41:33): 0
......

  • 主從庫各自先檢視一下慢查詢日誌、解析binlog，並分析慢查詢日誌（這裡的步驟是為了與後續執行完成大事務後的分析結果做對比，沒有對比就沒有傷害嘛）

# 主從庫慢查詢日誌
## 檢視主庫慢查詢日誌檔案，可以發現並沒有慢查詢日誌內容
[root@node1 ~]# cat /data//mysqldata1/slowlog/slow-query.log    
/usr/local/mysql/bin/mysqld, Version: 5.7.27-log (MySQL Community Server (GPL)). started with:
Tcp port: 3306 Unix socket: /home/mysql/data/mysqldata1/sock/mysql.sock
Time Id Command Argument
......
[root@node1 ~]# 
## 檢視從庫慢查詢日誌檔案，可以發現仍然沒有慢查詢日誌內容
[root@node2 ~]# cat /data//mysqldata1/slowlog/slow-query.log 
/usr/local/mysql/bin/mysqld, Version: 5.7.27-log (MySQL Community Server (GPL)). started with:
Tcp port: 3306 Unix socket: /home/mysql/data/mysqldata1/sock/mysql.sock
Time Id Command Argument
......
[root@node2 ~]# 
# 主從庫解析binlog，並分析慢查詢日誌
## 主庫解析最後一個binlog，並使用pt-query-digest工具進行慢查詢日誌分析
[root@node1 binlog]# mysqlbinlog -vv mysql-bin.000023 > a.sql
[root@node1 binlog]# pt-query-digest --type=binlog a.sql
...... 解析結果詳見下圖1
## 從庫解析最後一個binlog，並使用pt-query-digest工具進行慢查詢日誌分析
[root@node2 binlog]# mysqlbinlog -vv mysql-bin.000023 > b.sql
[root@node2 binlog]# pt-query-digest --type=binlog b.sql
......解析結果詳見下圖2
  • pt-query_digest 解析結果截圖

    • 圖1（主庫）


    • 圖2（從庫）


  • 關於主從庫binlog解析中，exec_time大於0秒的事務比對資訊如下，通過這些資訊可以看到，在從庫回放binlog時，事務的執行時間被拉長了（exec_time這個屬性的統計時間，是從每個事務修改的第一行記錄開始計時，直到事務提交完成為止，期間，如果事務存在鎖等待，則鎖等待的時間也會被一併計算在內。但是要注意，在一個事務包含多個SQL語句時，或者中間夾雜著一些操作間隔時間，例如sleep函式等，那麼這個值就不準確，但在我們的測試案例中，一個事務只修改一行記錄，所以這個時間在這裡是準確的，因此在這裡可以認為該值為這個事務真正執行的總時間）

# 主庫（從這裡可以看到，exec_time>0的記錄為1行，所以主庫的binlog分析結果中，第一個語句也是唯一的一個語句的Exec time行的Total列是1S）
[root@node1 binlog]# cat a.sql |grep exec_time |grep -v 'exec_time=0'
#190911 13:52:26 server id 33061 end_log_pos 1010517 CRC32 0x9481512e Query thread_id=96524 exec_time=1 error_code=0
# 從庫（從這裡可以看到，exec_time>0的有10行記錄，每行都是1，所以從庫的binlog分析結果中，第一個語句也是唯一的一個語句的Exec time行的Total列是10S）
[root@node2 binlog]# cat b.sql |grep exec_time |grep -v 'exec_time=0' 
#190911 13:42:44 server id 33061 end_log_pos 181363 CRC32 0x0be0bb2f Query thread_id=88584 exec_time=1 error_code=0
#190911 13:42:45 server id 33061 end_log_pos 182787 CRC32 0x86386f64 Query thread_id=88587 exec_time=1 error_code=0
#190911 13:44:26 server id 33061 end_log_pos 323911 CRC32 0x258368bc Query thread_id=89320 exec_time=1 error_code=0
#190911 13:46:16 server id 33061 end_log_pos 477703 CRC32 0xb91bf3e6 Query thread_id=90964 exec_time=1 error_code=0
#190911 13:47:04 server id 33061 end_log_pos 545343 CRC32 0x8dae4390 Query thread_id=91691 exec_time=1 error_code=0
#190911 13:48:53 server id 33061 end_log_pos 697711 CRC32 0xcbe1b667 Query thread_id=93332 exec_time=1 error_code=0
#190911 13:48:54 server id 33061 end_log_pos 698423 CRC32 0x44114126 Query thread_id=93338 exec_time=1 error_code=0
#190911 13:50:41 server id 33061 end_log_pos 847943 CRC32 0x27c5a588 Query thread_id=94939 exec_time=1 error_code=0
#190911 13:52:26 server id 33061 end_log_pos 995327 CRC32 0x3307103c Query thread_id=96524 exec_time=1 error_code=0
#190911 13:53:19 server id 33061 end_log_pos 1069375 CRC32 0x0540667c Query thread_id=97310 exec_time=1 error_code=0

  • 現在，準備工作已經就緒，在主從庫中執行切換binlog，準備入場了

mysql > flush binary logs;

3、執行大事務

  • 首先，在主從庫中，各自執行一個按照指定的時間間隔迴圈列印資料庫redo log、binlog、ibdata、undo、表資料檔案寫盤的吞吐統計指令碼（指令碼程式碼詳見文末的下載連結）

# 該指令碼的作用是，按照指定間隔時間，從sys.x$io_global_by_file_by_bytes檢視中抓取檔案IO吞吐資料，該檢視中的資料基本可以認為是實時資料（詳情可檢視微信公眾號"沃趣技術"中的sys schema系列文章）。注意，針對主庫執行的指令碼中的mysql_ip引數修改為主庫IP，針對從庫執行的指令碼中mysql_ip引數修改為從庫IP
## 主庫（執行列印結果詳見下圖3）
[root@node1 ~]# sh count_mysql_disk_file_io.sh
## 從庫（執行列印結果詳見下圖4）
[root@node2 ~]# sh count_mysql_disk_file_io.sh
  • count_mysql_disk_file_io.sh指令碼列印截圖如下

    • 圖3（主庫）


    • 圖4（從庫）


  • 從圖3和圖4的比對結果來看，主從庫中都頻繁抓取到redo log和binlog有0~30KB範圍內的吞吐，說明此時，對於主庫中的UPDATE事務產生的資料檔案的吞吐量，在主從庫中是一致的

  • 現在，登入到主從資料庫中，各自使用sys.io_global_by_file_by_bytes檢視查詢當前主從庫中相關的資料檔案總吞吐統計值，以便後續大事務執行完成之後，再次抓取該統計值進行對比

# 主庫（執行結果詳見下圖5）
mysql > select * from sys.io_global_by_file_by_bytes where count_read!=0 order by count_read desc;
......
# 從庫（執行結果詳見下圖6）
mysql > select * from sys.io_global_by_file_by_bytes where count_read!=0 order by count_read desc;
......
  • sys.io_global_by_file_by_bytes檢視的執行結果截圖如下

    • 圖5（主庫）


    • 圖6（從庫）

  • 從圖5和圖6的對比資料可以看到，主庫的寫流量主要在binlog上，而且讀流量在binlog上也有幾兆；從庫的寫流量主要在relay log上，讀流量也主要在relay log；另外，proc.MYD檔案的讀流量主要是因為相關的輔助指令碼持續呼叫相關的查詢檢視產生的。當然，這裡的資料可能不準確（例如：從庫中relay log在重放完成之後，如果啟用了purge_relay_log引數，會被自動清理，在這個檢視中也就看不到被清理的relay log檔案相關的統計資訊了），但不要緊，這裡僅僅只是讓我們知曉一個流量的量級，等到後續大事務執行完成之後，再次查詢該檢視中的資料，你將會發現大事務執行前後相關的資料檔案在讀寫流量上存在量級上的差異

  • 現在，登入到主庫中，執行修改資料量級超過400W行的UPDATE語句（給定id值範圍不要與exec_parallel_sql_master.sh指令碼中給定的id值發生鎖衝突），這裡我們以操作sbtest1表為例執行大事務

mysql > use sbtest
Database changed
# 注意，這裡不要加limit，會干擾exec_parallel_sql_master.sh和exec_parallel_sql_slave.sh指令碼中的判斷邏輯（通過上述環境資訊可知，我們造數為1000W，且自增不長設定為2，所以，id>10000000大概是500W行的資料量級別）
mysql > explain update sbtest1 set k=k+1 where id>10000000;
+----+-------------+---------+------------+-------+---------------+---------+---------+-------+---------+----------+-------------+
| id | select_type | table | partitions | type | possible_keys | key | key_len | ref | rows | filtered | Extra |
+----+-------------+---------+------------+-------+---------------+---------+---------+-------+---------+----------+-------------+
| 1 | UPDATE | sbtest1 | NULL | range | PRIMARY | PRIMARY | 4 | const | 4938195 | 100.00 | Using where |
+----+-------------+---------+------------+-------+---------------+---------+---------+-------+---------+----------+-------------+
1 row in set (0.00 sec)
# 使用顯式的事務執行該語句
mysql > begin; update sbtest1 set k=k+1 where id>10000000;commit;
......

  • 在主庫大事務未執行完成之前，可在主庫反覆執行show processlist檢視執行緒狀態資訊（該步驟不是必須的）

mysql > show processlist;
+--------+------+--------------------+--------+------------------+-------+---------------+--------------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+--------+------+--------------------+--------+------------------+-------+----------------+--------------------------------------------+
| 4 | repl | 10.10.30.163:33375 | NULL | Binlog Dump GTID | 80999 | Master has sent all binlog to slave; waiting for more updates | NULL |
| 5 | repl | 10.10.30.164:49847 | NULL | Binlog Dump GTID | 80998 | Master has sent all binlog to slave; waiting for more updates | NULL |
| 88201 | root | localhost | sbtest | Query | 19 | updating | update sbtest1 set k=k+1 where id>10000000 |
| 107409 | root | localhost | NULL | Query | 0 | starting | show processlist |
+--------+------+--------------------+--------+------------------+-------+-----------------+--------------------------------------------+
4 rows in set (0.00 sec)

  • 檢視主庫中資料檔案的流量吞吐情況（該資訊為count_mysql_disk_file_io.sh指令碼的列印日誌），從下圖中可以發現，事務未執行完成之前，除了binlog之外，表空間檔案、共享表空間、undo、redo的磁碟流量都有不同程度的大幅增加，說明事務未提交時，這幾種檔案都會寫盤且，binlog不寫盤（以往沒少聽說過“事務提交之後，髒頁在後臺重新整理”這種話吧？嘿，這話聽起來挺有迷惑性的。事務提交之後，後臺執行緒的確會做刷髒的事情，不過，這句話可沒說事務未提交之前後臺執行緒不刷髒。這樣設計顯然是合理的，否則大事務產生的髒頁總量超過記憶體時，事務就無法執行了）

  • 持續觀察主庫中的語句執行進度，直到執行完成（這一步可千萬不要中斷了，否則上述一系列步驟就要重新來過了）

mysql > begin; update sbtest1 set k=k+1 where id>10000000;commit;
Query OK, 0 rows affected (0.00 sec)  # 這裡是begin語句執行的時間，為0.00 sec
Query OK, 5000000 rows affected (2 min 58.55 sec)  # 這裡可以看到UPDATE語句本身執行了2 min 58.55 sec
Rows matched: 5000000 Changed: 5000000 Warnings: 0
Query OK, 0 rows affected (5.01 sec) # 從這裡可以看到，這裡是UPDATE語句後邊的commit語句，執行了5.01 sec

  • 待到主庫大事務執行完成之後，迅速觀察從庫的複製延遲情況，並檢視下show processlist;

# 檢視從庫複製延遲
mysql > show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 10.10.30.162
                  Master_User: repl
                  Master_Port: 3306
                Connect_Retry: 10
              Master_Log_File: mysql-bin.000025
          Read_Master_Log_Pos: 139733
               Relay_Log_File: mysql-relay-bin.000064
                Relay_Log_Pos: 642431
        Relay_Master_Log_File: mysql-bin.000024
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
......
          Exec_Master_Log_Pos: 642218
              Relay_Log_Space: 1909355863
......
        Seconds_Behind_Master: 101 # 從這裡可以看到，這個延遲數值已經有126秒了（雖然不準確，但是這個量級的延遲數字已經足夠說明覆制存在延遲了）
......
           Retrieved_Gtid_Set: 6f43ada4-d39d-11e9-9c97-5254002a54f2:1-27419
            Executed_Gtid_Set: 6a3227ed-d39d-11e9-a7b0-525400c33752:1-2,
6f43ada4-d39d-11e9-9c97-5254002a54f2:1-27224
                Auto_Position: 1
         Replicate_Rewrite_DB:
                 Channel_Name:
           Master_TLS_Version:
1 row in set (0.00 sec)
# 檢視從庫執行緒狀態
mysql > show processlist;
+--------+-------------+-----------+------+---------+-------+----------------+--------------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+--------+-------------+-----------+------+---------+-------+---------------+--------------------------------------------+
| 5 | system user | | NULL | Connect | 81296 | Waiting for master to send event | NULL |
| 6 | system user | | NULL | Connect | 0 | Reading event from the relay log | NULL |
# 大事務的SQL語句在這裡（注意，row格式下資料回放的是資料的逐行變更日誌，並不是SQL語句文字，這裡看到的SQL語句文字來自binlog_rows_query_log_events=ON引數記錄的註釋性的原始SQL文字，在從庫回放主庫binlog時會當做註釋用途展示在這裡）
| 7 | system user | | NULL | Connect | 316 | Executing event | update sbtest1 set k=k+1 where id>10000000 |
| 8 | system user | | NULL | Connect | 10270 | Waiting for an event from Coordinator | NULL |
| 9 | system user | | NULL | Connect | 81296 | Waiting for an event from Coordinator | NULL |
| 10 | system user | | NULL | Connect | 81296 | Waiting for an event from Coordinator | NULL |
| 11 | system user | | NULL | Connect | 81296 | Waiting for an event from Coordinator | NULL |
| 12 | system user | | NULL | Connect | 81296 | Waiting for an event from Coordinator | NULL |
| 13 | system user | | NULL | Connect | 81296 | Waiting for an event from Coordinator | NULL |
| 14 | system user | | NULL | Connect | 81296 | Waiting for an event from Coordinator | NULL |
| 15 | system user | | NULL | Connect | 81296 | Waiting for an event from Coordinator | NULL |
| 16 | system user | | NULL | Connect | 81296 | Waiting for an event from Coordinator | NULL |
| 17 | system user | | NULL | Connect | 81296 | Waiting for an event from Coordinator | NULL |
| 18 | system user | | NULL | Connect | 81296 | Waiting for an event from Coordinator | NULL |
| 19 | system user | | NULL | Connect | 81296 | Waiting for an event from Coordinator | NULL |
| 20 | system user | | NULL | Connect | 81296 | Waiting for an event from Coordinator | NULL |
| 21 | system user | | NULL | Connect | 81296 | Waiting for an event from Coordinator | NULL |
| 22 | system user | | NULL | Connect | 81296 | Waiting for an event from Coordinator | NULL |
| 107297 | root | localhost | NULL | Sleep | 596 | | NULL |
| 127830 | root | localhost | NULL | Query | 0 | starting | show processlist |
+--------+-------------+-----------+------+---------+-------+-----------------+--------------------------------------------+
20 rows in set (0.00 sec)

  • 順便看一眼從庫的資料檔案流量探測指令碼的情況（這些資訊來自指令碼count_mysql_disk_file_io.sh的列印日誌），從下圖中標記的地方，對比下主庫的資料檔案流量列印日誌，可以發現它們在量級上是差不多的

  • 關注check_slave_delay.sh指令碼的列印情況，當發現複製延遲降為0時，表示大事務已經在從庫回放完成了，通過check_slave_delay.sh指令碼列印的資訊，我們可以非常直觀地看到，從07分26秒開始出現5秒延遲，10分54秒延遲降為0，毛估估的算一下，這個大事務在從庫中的執行時間為3分28秒（該事務在主庫中的執行時長為3分4秒），如下

    • 探測到開始大幅延遲的時間點


    • 探測到延遲結束的時間點


  • 此時，大事務在主從庫都已經執行完成，可以將所有輔助指令碼停止執行了

  • 上述對於主從庫資料檔案的流量探測截圖中（這裡指的是count_mysql_disk_file_io.sh指令碼列印日誌截圖）都沒有擷取到binlog磁碟流量大幅增加的資訊，難道這個大事務沒寫binlog？非也，因為binlog不是持續寫的，在事務持久化的兩階段提交中，事務持久化完成之後，寫binlog就結束了，因為人為操作的截圖，錯過列印的時間點沒有擷取到，我們開啟指令碼日誌找找看

# 主庫（從下面找到的資訊來看，大事務在主庫的提交過程中，5秒左右就將binlog落盤完成了，緊隨其後，大約有8秒的時間大量binlog讀盤操作，這裡是主庫通過binlog dump執行緒將binlog傳送給從庫的過程。注意，如果sync_binlog不為1，那麼在這個時候是否有大量binlog讀盤操作不確定，有興趣的同學自行測試）
[root@node1 ~]# grep -E 'Wed Sep|binlog' /tmp/count_mysql_disk_file_io.sh.log
---------------------------Wed Sep 11 14:07:19 CST 2019-------------------------
binlog 本次寫盤差異量：count_read:4，total_read:2.82 KiB，count_write:2，total_written:1.41 KiB
---------------------------Wed Sep 11 14:07:20 CST 2019-------------------------
binlog 本次寫盤差異量：count_read:4，total_read:2.82 KiB，count_write:51695，total_written:395.17 MiB
---------------------------Wed Sep 11 14:07:22 CST 2019-------------------------
binlog 本次寫盤差異量：count_read:0，total_read:0 bytes，count_write:72236，total_written:552.22 MiB
---------------------------Wed Sep 11 14:07:23 CST 2019-------------------------
binlog 本次寫盤差異量：count_read:0，total_read:0 bytes，count_write:63161，total_written:482.84 MiB
---------------------------Wed Sep 11 14:07:24 CST 2019-------------------------
binlog 本次寫盤差異量：count_read:0，total_read:0 bytes，count_write:51005，total_written:389.92 MiB
---------------------------Wed Sep 11 14:07:25 CST 2019-------------------------
binlog 本次寫盤差異量：count_read:35448，total_read:276.85 MiB，count_write:10，total_written:7.24 KiB
---------------------------Wed Sep 11 14:07:26 CST 2019-------------------------
binlog 本次寫盤差異量：count_read:63276，total_read:494.19 MiB，count_write:2，total_written:1.41 KiB
---------------------------Wed Sep 11 14:07:28 CST 2019-------------------------
binlog 本次寫盤差異量：count_read:72738，total_read:568.09 MiB，count_write:2，total_written:1.41 KiB
---------------------------Wed Sep 11 14:07:29 CST 2019-------------------------
binlog 本次寫盤差異量：count_read:63220，total_read:493.69 MiB，count_write:2，total_written:1.41 KiB
---------------------------Wed Sep 11 14:07:30 CST 2019-------------------------
binlog 本次寫盤差異量：count_read:73495，total_read:574.16 MiB，count_write:4，total_written:2.82 KiB
---------------------------Wed Sep 11 14:07:31 CST 2019-------------------------
binlog 本次寫盤差異量：count_read:60512，total_read:472.76 MiB，count_write:2，total_written:1.41 KiB
---------------------------Wed Sep 11 14:07:32 CST 2019-------------------------
binlog 本次寫盤差異量：count_read:69182，total_read:540.49 MiB，count_write:2，total_written:1.41 KiB
---------------------------Wed Sep 11 14:07:33 CST 2019-------------------------
binlog 本次寫盤差異量：count_read:27818，total_read:217.25 MiB，count_write:2，total_written:1.41 KiB
---------------------------Wed Sep 11 14:07:35 CST 2019-------------------------
binlog 本次寫盤差異量：count_read:4，total_read:2.82 KiB，count_write:2，total_written:1.41 KiB
# 從庫（從下面找到的資訊來看，大事務在從庫的提交過程中，6秒左右就將binlog落盤完成了。注意，這裡指的是從庫將大事務回放完成之後，寫入自己的binlog檔案的流量，而不是從庫拉取主庫binlog寫relay log的流量）
[root@node2 ~]# grep -E 'Wed Sep|binlog' /tmp/count_mysql_disk_file_io.sh.log
......
---------------------------Wed Sep 11 14:10:48 CST 2019-------------------------
binlog 本次寫盤差異量：count_read:0，total_read:0 bytes，count_write:0，total_written:0 bytes
---------------------------Wed Sep 11 14:10:49 CST 2019-------------------------
binlog 本次寫盤差異量：count_read:0，total_read:0 bytes，count_write:56748，total_written:433.82 MiB
---------------------------Wed Sep 11 14:10:50 CST 2019-------------------------
binlog 本次寫盤差異量：count_read:0，total_read:0 bytes，count_write:76567，total_written:585.33 MiB
---------------------------Wed Sep 11 14:10:51 CST 2019-------------------------
binlog 本次寫盤差異量：count_read:0，total_read:0 bytes，count_write:63901，total_written:488.50 MiB
---------------------------Wed Sep 11 14:10:52 CST 2019-------------------------
binlog 本次寫盤差異量：count_read:0，total_read:0 bytes，count_write:40881，total_written:312.51 MiB
---------------------------Wed Sep 11 14:10:54 CST 2019-------------------------
binlog 本次寫盤差異量：count_read:0，total_read:0 bytes，count_write:382，total_written:263.80 KiB
---------------------------Wed Sep 11 14:10:55 CST 2019-------------------------
binlog 本次寫盤差異量：count_read:0，total_read:0 bytes，count_write:38，total_written:26.42 KiB
---------------------------Wed Sep 11 14:10:56 CST 2019-------------------------
binlog 本次寫盤差異量：count_read:0，total_read:0 bytes，count_write:2，total_written:1.39 KiB
......
  • 上述程式碼段可能不便閱讀，這裡將上述內容截圖列出

    • 圖7（主庫）


    • 圖8（從庫）


4、分析大事務的影響

  • 首先在主從庫分別檢視慢查詢日誌檔案

# 主庫（發現大事務語句已經被記錄在案了）
[root@node1 ~]# cat /data/mysqldata1/slowlog/slow-query.log
/usr/local/mysql/bin/mysqld, Version: 5.7.27-log (MySQL Community Server (GPL)). started with:
Tcp port: 3306 Unix socket: /home/mysql/data/mysqldata1/sock/mysql.sock
Time Id Command Argument
......
# Time: 2019-09-11T14:07:20.291512+08:00
# User@Host: root[root] @ localhost [] Id: 88201
# Query_time: 178.546835 Lock_time: 0.000057 Rows_sent: 0 Rows_examined: 5000000
use sbtest;
SET timestamp=1568182040;
update sbtest1 set k=k+1 where id>10000000;
# Time: 2019-09-11T14:07:25.307290+08:00
# User@Host: admin[admin] @ [10.10.30.16] Id: 109940
# Query_time: 4.375712 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
SET timestamp=1568182045;
commit;
# 從庫（咦，在從庫的慢日誌中，大事務逃脫了？嗯，看起來是的，因為咋們的復現環境是使用的row格式複製，回放過程中有效的日誌記錄只有資料的逐行變更記錄，並不包含語句文字，不會完整地經過SQL層的一些流程，也就無法記錄到慢查詢日誌中）
[root@node2 ~]# cat /data//mysqldata1/slowlog/slow-query.log
/usr/local/mysql/bin/mysqld, Version: 5.7.27-log (MySQL Community Server (GPL)). started with:
Tcp port: 3306 Unix socket: /home/mysql/data/mysqldata1/sock/mysql.sock
Time Id Command Argument
......
  • 順便用pt-query-digest工具解析下主庫的慢查詢日誌，截個圖列出

    • 圖9（主庫）


    • 圖10（從庫）


  • 現在，在主從庫分別解析binlog日誌檢視，並使用pt-query-digest工具分析binlog

# 主庫（解析最後2個binlog，為什麼要解析最後2個binlog呢，因為大事務一定不在倒數第一個binlog中，大事務執行完成之後，binlog尺寸會因為超過了max_binlog_size設定的大小，而立即進行日誌切換，當然，如果大事務執行完成之後，後續沒有新的事務進來，binlog就不一定會立即進行切換了）
[root@node1 binlog]# ls -lh
total 13G
......
-rw-r----- 1 mysql mysql 1.8G Sep 11 14:07 mysql-bin.000024
-rw-r----- 1 mysql mysql 449K Sep 11 14:12 mysql-bin.000025
-rw-r----- 1 mysql mysql 1.3K Sep 11 14:07 mysql-bin.index
[root@node1 binlog]# mysqlbinlog mysql-bin.000024 mysql-bin.000025 > b.sql
[root@node1 binlog]# ls -lh b.sql
-rw-r--r-- 1 root root 2.5G Sep 11 15:38 b.sql
[root@node1 binlog]# pt-query-digest --type=binlog b.sql
# 大事務的解析結果比較大，使用pt-query-digest工具解析會發生(core dumped)，pt-query-digest工具解析時不需要用到BINLOG編碼，所以，這裡可以將binlog中不需要的BINLOG編碼過濾掉再進行解析
[root@node1 binlog]# grep -E '\#|/\*|SET|BEGIN|COMMIT|DELIMITER' b.sql > b.txt
[root@node1 binlog]# ls -lh b.txt
-rw-r--r-- 1 root root 28M Sep 11 16:52 b.txt
[root@node1 binlog]# pt-query-digest --type=binlog b.txt
......  # 解析結果詳見圖11
# 從庫
[root@node2 binlog]# ls -lh
total 13G
......
-rw-r----- 1 mysql mysql 1.8G Sep 11 14:10 mysql-bin.000024
-rw-r----- 1 mysql mysql 442K Sep 11 14:12 mysql-bin.000025
[root@node2 binlog]# mysqlbinlog mysql-bin.000024 mysql-bin.000025 > c.sql
[root@node2 binlog]# ls -lh c.sql
-rw-r--r-- 1 root root 2.5G Sep 11 15:42 c.sql
[root@node2 binlog]# grep -E '\#|/\*|SET|BEGIN|COMMIT|DELIMITER' c.sql > c.txt
[root@node2 binlog]# pt-query-digest --type=binlog c.txt
...... # 解析結果詳見圖12
  • pt-query_digest 解析結果截圖

    • 圖11（主庫）


    • 圖12（從庫）


  • 從上面兩個圖的對比結果來看
    • 大事務在主庫binlog中逃脫了，因為row格式中有效的binlog記錄的是資料的逐行變更資料，而非SQL語句文字，同理，在從庫中也應該不會記錄該大事務的語句
    • 從庫的binlog分析結果中，語句的總執行時間大幅增加。在上文中更早之前我們通過分析binlog已經知道，從庫回放會拉長事務的執行時間，但是圖12中從庫binlog解析記錄的SQL總執行時間為43853s，換算成小時，約12個小時，可我們在這裡，整個操作過程不到一個小時，很顯然，pt-query-digest工具的分析結果中，是將所有BEGIN語句的時間都加在一起了，又因為在測試環境中的從庫啟用了多執行緒複製，每個worker執行緒獨立執行，也就是說，假設有N個worker執行緒同時在回放事務，而每個worker執行緒同時將執行時間拉長1S，那麼，pt-query-digest工具的統計結果中的總延遲時間就變成了N*1S=NS，以此推理可得，大事務在執行過程中，小事務分配binlog event變慢了，又或者被阻塞了，so...

    • 下面，我同樣也將exec_time屬性不為0的記錄過濾出來瞧瞧

# 主庫（發現主庫一共有2行exec_time屬性不為0的記錄）
[root@node1 binlog]# cat b.txt |grep exec_time |grep -v 'exec_time=0'
#190911 14:07:21 server id 33061 end_log_pos 338 CRC32 0xdd75591e Query thread_id=109957 exec_time=4 error_code=0
#190911 14:07:22 server id 33061 end_log_pos 1061 CRC32 0x9482c46d Query thread_id=109974 exec_time=3 error_code=0
# 從庫（發現從庫一共有423行exec_time屬性不為0的記錄）
[root@node2 binlog]# cat c.txt |grep exec_time |grep -v 'exec_time=0'
......
#190911 14:07:21 server id 33061 end_log_pos 367 CRC32 0xe616b934 Query thread_id=109957 exec_time=212 error_code=0
#190911 14:07:22 server id 33061 end_log_pos 1079 CRC32 0x03ca1c89 Query thread_id=109974 exec_time=211 error_code=0
#190911 14:07:25 server id 33061 end_log_pos 1791 CRC32 0xc4e998ea Query thread_id=110012 exec_time=208 error_code=0
......
[root@node2 binlog]# cat c.txt |grep exec_time |grep -v 'exec_time=0' |wc -l
423

  • 現在，主從庫分別檢視指令碼日誌（主庫中檢視exec_parallel_sql_master.sh指令碼的執行日誌，從庫中檢視exec_parallel_sql_slave.sh指令碼的執行日誌），看看主庫是否有發生較長時間的寫阻塞，從庫是否有發生較長時間的讀阻塞（注：以下程式碼段中為部分日誌，完整日誌請從文末的下載連結中獲取）

# 主庫（發現了SQL被阻塞的記錄，從下面show processlist輸出結果中可以看到，兩個update語句只修改一行記錄，原本是不會被阻塞的，但是，現在，因為大事務，發生了阻塞，從後續的sys.session檢視這裡可以大致判斷，其他小事務由於大事務在提交binlog階段發生了阻塞，甚至導致出現了2個一模一樣的UPDATE SQL，因為前一個SQL被阻塞未執行完，後一個完全一樣的SQL進入之後甚至導致出現了鎖等待）
[root@node1 binlog]# vim /tmp/exec_parallel_sql_master.sh.log
......
==============================================================================================
警告！SQL發生阻塞！！！！！！-----------------------------------------
==============================================================================================
show processlist資訊如下：---------------------------------
Id User Host db Command Time State Info
4 repl 10.10.30.163:33375 NULL Binlog Dump GTID 81163 Master has sent all binlog to slave; waiting for more updates NULL
5 repl 10.10.30.164:49847 NULL Binlog Dump GTID 81162 Master has sent all binlog to slave; waiting for more updates NULL
88201 root localhost sbtest Query 4 starting commit
107409 root localhost NULL Sleep 164 NULL
109940 admin 10.10.30.16:62563 sbtest Query 4 starting commit
109957 admin 10.10.30.16:62597 sbtest Query 3 updating update sbtest1 set k=k+1 where id>1000000 limit 1
109974 admin 10.10.30.16:62631 sbtest Query 2 updating update sbtest1 set k=k+1 where id>1000000 limit 1
109991 admin 10.10.30.16:62665 NULL Query 0 starting show processlist
sys.session檢視資訊如下：---------------------------------
*************************** 1. row ***************************
                thd_id: 109982
               conn_id: 109940
                  user: admin@10.10.30.16
                    db: sbtest
               command: Query
                 state: starting
                  time: 4
     current_statement: commit
     statement_latency: 3.09 s
......
        current_memory: 0 bytes
             last_wait: wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_log
     last_wait_latency: Still Waiting
......
                   pid: 24345
          program_name: mysql
*************************** 2. row ***************************
# 鎖等待資訊
*************************** 1. row ***************************
*************************** 2. row ***************************
                wait_started: 2019-09-11 14:07:22
                    wait_age: 00:00:02
               wait_age_secs: 2
                locked_table: `sbtest`.`sbtest1`
                locked_index: PRIMARY
                 locked_type: RECORD
              waiting_trx_id: 49083
         waiting_trx_started: 2019-09-11 14:07:22
             waiting_trx_age: 00:00:02
     waiting_trx_rows_locked: 2
   waiting_trx_rows_modified: 0
                 waiting_pid: 109974
               waiting_query: update sbtest1 set k=k+1 where id>1000000 limit 1
             waiting_lock_id: 49083:41:6881:62
           waiting_lock_mode: X
             blocking_trx_id: 49082
                blocking_pid: 109957
              blocking_query: update sbtest1 set k=k+1 where id>1000000 limit 1
            blocking_lock_id: 49082:41:6881:62
          blocking_lock_mode: X
        blocking_trx_started: 2019-09-11 14:07:21
            blocking_trx_age: 00:00:03
    blocking_trx_rows_locked: 2
  blocking_trx_rows_modified: 0
     sql_kill_blocking_query: KILL QUERY 109957
sql_kill_blocking_connection: KILL 109957
*************************** 3. row ***************************
......
# 從庫（在從庫中並未發現SQL阻塞和鎖等待記錄）
[root@node2 ~]# cat /tmp/exec_parallel_sql_slave.sh.log |grep -E 'sys.session|wait_started'
......

  • 現在，登入到主從資料庫中，各自使用sys.io_global_by_file_by_bytes檢視查詢相關資料檔案的總吞吐統計資料

# 主庫（見圖13）
mysql > select * from sys.io_global_by_file_by_bytes where count_read!=0 order by count_read desc;
......
# 從庫（見圖14）
mysql > select * from sys.io_global_by_file_by_bytes where count_read!=0 order by count_read desc;
......
  • sys.io_global_by_file_by_bytes檢視的執行結果截圖

    • 圖13（主庫）


    • 圖14（從庫）


  • 從上述圖13和圖14中可以看到，吞吐統計資料都毫無懸念地大幅增加了，不過。。主庫中出現了一個臨時檔案/data/mysqldata1/tmpdir/MLrxkcac，讀取和寫入的總流量都為1.78G，從庫中也出現了一個臨時檔案/data/mysqldata1/tmpdir/MLirV7PX，讀取和寫入總流量也都為1.78G，額，還真是巧了，這個臨時檔案是做啥的呢？再仔細一看圖13中主庫的/data/mysqldata1/binlog/mysql-bin.000024檔案的寫入總流量也為1.78G，主從庫中出現的臨時檔案會不會跟寫binlog有啥關係呢？咋們來推導一下，大事務未提交時，binlog是不能落盤的，那整個事務的binlog日誌量往哪裡放呢？記憶體？那萬一記憶體不夠用怎麼辦？那寫磁碟吧？往哪兒寫呢？臨時檔案？會不會這裡看到的這個臨時檔案就是用來暫存未提交大事務的binlog的呢？

  • 檢視一下磁碟上的binlog檔案看看，從側面證實下推導的結論

# 檢視binlog目錄下的mysql-bin.000024檔案
[root@node1 binlog]# ls -lh
total 22G
......
-rw-r----- 1 mysql mysql 1.8G Sep 11 14:07 mysql-bin.000024 # 咦，不對啊，磁碟上這個檔案是1.8G，對不上？別慌，我們換個思路，繼續往下看
-rw-r----- 1 mysql mysql 449K Sep 11 14:12 mysql-bin.000025
# 會不會是單位演算法不一樣呢？sys.io_global_by_file_by_bytes檢視中的位元組流單位是使用sys.format_bytes()函式進行轉換的，那我們改用ls -l檢視，去掉-h選項檢視磁碟檔案，把位元組資料拿出來，使用資料庫中的sys.format_bytes()函式算算看
[root@node1 binlog]# ls -l
total 22186044
......
-rw-r----- 1 mysql mysql 1909214744 Sep 11 14:07 mysql-bin.000024  # 從這裡可以看到，位元組資料為1909214744
-rw-r----- 1 mysql mysql 459299 Sep 11 14:12 mysql-bin.000025
-rw-r----- 1 mysql mysql 1300 Sep 11 14:07 mysql-bin.index
# 登入資料庫算算
mysql > select sys.format_bytes(1909214744);
+------------------------------+
| sys.format_bytes(1909214744) |
+------------------------------+
| 1.78 GiB |  # 從這裡可以看到，正好1.78G
+------------------------------+
1 row in set (0.00 sec)

  • PS：對於ML開頭的臨時檔案，事務未執行提交之前，在ps中無法被捕獲到，但可以在作業系統層面使用lsof命令檢視，如下（看到某個檔案的位元組數在不斷增加的時候，就表示mysqld程式正在不斷地使用臨時檔案存放一些臨時資料，但是，當事務提交時，lsof命令捕獲到的臨時檔案條目的位元組數會被清零）：

5、優化大事務的影響

  • 主庫引數優化，新增如下兩個優化引數

# 將優化引數持久化
[root@node1 binlog]# cat /etc/my.cnf
......
[mysqld]
binlog_transaction_dependency_tracking=WRITESET
transaction_write_set_extraction=XXHASH64
......
# 也可以動態修改，但是順序不能搞錯，需要先修改transaction_write_set_extraction引數為XXHASH64，否則會報錯
mysql > set global transaction_write_set_extraction=XXHASH64;
Query OK, 0 rows affected (0.00 sec)
mysql > set global binlog_transaction_dependency_tracking=WRITESET;
Query OK, 0 rows affected (0.00 sec)
  • 現在，咋們將上述所有步驟重新跑一下，看看大事務是否會阻塞其他的小事務（過程略）
  • 從測試結果來看，很遺憾，沒有太大的優化效果
    • 對於主庫來說，小事務仍然會在大事務提交binlog階段發生短暫阻塞（如果磁碟吞吐不太好，那這個問題可大可小了）
    • 對於從庫來說，複製延遲仍然存在，但通過pt-query-digest工具解析binlog結果來看，總執行時間減小了一些，但仍然與未優化前處於同一個量級
  • 那是不是說這兩個優化引數沒啥用呢？不是的，測試結果只能證明，這兩個引數的優化效果對大事務場景沒太大用處，但對於其他一些特定場景就可能有用。那在什麼場景下有用呢？這個話題，我們們日後再聊
  • 現在回過頭來繼續聊大事務究竟怎麼搞呢？當你沒有辦法去優化某件某個大事務的，最好的辦法就是...消滅它，如何消滅大事務呢？回到文章開頭那句話：“在開發規範裡明令禁止大事務（單個事務操作的資料量不建議超過10000行），儘可能將大事務拆分為小事務，即便特殊情況不得不跑大事務，至少也要在會話級別將binlog格式改成statement。
  • 最後
    • 特別強調一下，對於MySQL InnoDB儲存引擎來說，建議設定主鍵或唯一索引，再不濟也要有二級索引，否則，那感覺一定很酸爽，你可以準備兩張沒有任何索引的表，用上述過程操作一遍試試看！
    • 另外，喜歡用級聯複製的同學們注意了，除非必須，否則不建議使用級聯複製，以現在的伺服器硬體配置來說，使用級聯複製帶來的好處還不如帶來的問題多

6、附錄

  • 上文中使用到的相關指令碼和相關日誌檔案下載連結如下
  • PS：
    • 關於exec_time屬性的詳細解釋，詳情可參考 高鵬（重慶八怪）的《深入理解MySQL主從原理》專欄中的第八講

    • 關於大事務binlog未落盤之前，是否會寫臨時檔案的詳細解釋，詳情可參考 高鵬（重慶八怪）的《深入理解MySQL主從原理》專欄中的第十三、第十四講。最後，附一張高清圖（該圖為第十四講文末的高清圖），留意左側綠色方框內的內容



揭祕MySQL 主從環境中大事務的傳奇事蹟

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

相關文章