導語

這個問題，很久以前，筆者只是大概知道其中的原理，知道它就是長這樣的，但並沒有做過具體的案例分析。

直到某客戶問起這個問題的時候，才發覺空口無憑講不太清楚，遂現場給客戶演示了一番才鬆了口氣，也順便把演示過程記錄了下來，整理成文。下面請跟隨我們一起來一探究竟吧！

伺服器環境

1. 作業系統版本：CentOS release 6.5 (Final)

2. MySQL 版本：Oracle MySQL 5.7.20

3. MySQL 關鍵引數：innodb_flush_log_at_trx_commit=1; sync_binlog=1; binlog_format=row; gtid_mode=on; enforce_gtid_consistency=on

4. 驗證所需資料：sysbench壓測之後遺留的測試資料（可自行造數，只需要一張表中有一條資料即可）

驗證準備

登入到資料庫中，手動滾動一下binlog檔案

root@localhost : sbtest 03:27:34> flush binary logs;select now();
Query OK, 0 rows affected (0.01 sec)
+---------------------+
| now() |
+---------------------+
| 2018-10-04 15:31:55 |  # 滾動binlog的時間點為2018-10-04 15:31:55
+---------------------+
1 row in set (0.00 sec)

解析一下最新的Binlog檔案中的內容及其對應的時間點資訊

[root@localhost binlog]# mysqlbinlog -vv mysql-bin.000460 
mysqlbinlog: [Warning] unknown variable 'loose_default-character-set=utf8'
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#181004 15:31:55 server id 3306111 end_log_pos 123 CRC32 0x9cc61928 Start: binlog v 4, server v 5.7.20-log created 181004 15:31:55
# Warning: this binlog is either in use or was not closed properly.
BINLOG '
68G1Ww9/cjIAdwAAAHsAAAABAAQANS43LjIwLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
ASgZxpw=
'/*!*/;
# at 123
#181004 15:31:55 server id 3306111 end_log_pos 194 CRC32 0xc34422d7 Previous-GTIDs
# ec123678-5e26-11e7-9d38-000c295e08a0:182318-199336
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

從上述binlog的解析內容來看，當前最新的binlog中，除了檔案頭的event之外，並沒有其他使用者資料產生的event資料，且檔案頭的所有event的時間點都為 2018-10-04 15:31:55 ，這個時間點也是在資料庫中手動執行binlog滾動語句的時間點，也就是說：binlog檔案頭的event是在binlog滾動時就已經產生且寫入到了最新的binlog中，且這些event與使用者資料無關。

驗證過程

接下來我們模擬使用者對資料執行update操作，且為了驗證需要，我們使用了顯式事務，且在事務執行過程中人為加入了停頓，以便更清晰地看到binlog中的event是如何記錄的。

首先，登入到資料庫中，顯式開啟一個事務。

# 查詢測試資料，以便後續編寫update語句
root@localhost : sbtest 03:31:55> select * from sbtest1 limit 1;
+----+---------+-------------------------------------------------------------------------------------------------------------------------+-----+
| id | k | c | pad |
+----+---------+-------------------------------------------------------------------------------------------------------------------------+-----+
| 21 | 2483477 | 09279210219-37745839908-56185699327-79477158641-86711242956-61449540392-42622804506-61031512845-36718422840-11028803849 | xxx |
+----+---------+-------------------------------------------------------------------------------------------------------------------------+-----+
1 row in set (0.00 sec)
# 顯式開啟一個事務
root@localhost : sbtest 03:32:17> begin;select now();
Query OK, 0 rows affected (0.00 sec)
+---------------------+
| now() |
+---------------------+
| 2018-10-04 15:33:02|  # begin語句時間點為 2018-10-04 15:33:02
+---------------------+
1 row in set (0.00 sec)

這個時候，binlog中還未記錄新事務的binlog日誌，等待幾十秒之後，再在資料庫中執行update語句修改k列值（這裡是單行修改，且sbtest1表的id列為主鍵，所以update語句執行時間在這裡是極小的，可以忽略不計）

root@localhost : sbtest 03:33:02> update sbtest1 set k=k+1 where id=21;select now();
Query OK, 1 row affected (0.00 sec)
Rows matched: 1 Changed: 1 Warnings: 0
+---------------------+
| now() |
+---------------------+
| 2018-10-04 15:35:21 |  # update語句執行的時間點為 2018-10-04 15:35:21
+---------------------+
1 row in set (0.00 sec)

這個時候，binlog中仍然還未記錄新事務的binlog日誌（因為事務並沒有提交，binlog只會在事務提交時才會寫入binlog檔案中），現在，我們對該顯式事務執行commit語句提交事務。

root@localhost : sbtest 03:35:21> commit;select now();
Query OK, 0 rows affected (0.01 sec)
+---------------------+
| now() |
+---------------------+
| 2018-10-04 15:36:42 | # commit語句執行的時間點為 2018-10-04 15:36:42
+---------------------+
1 row in set (0.00 sec)

現在，我們解析最新的binlog檔案，檢視此時binlog中是如何記錄該事務產生的event資料的（注意：binlog 中每個event的時間點資訊是在生成event的時候產生的），為了方便大家閱讀，後續內容將對binlog做分段說明。

（1）解析binlog

[root@localhost binlog]# mysqlbinlog -vv mysql-bin.000460 
......

（2）以下內容為binlog檔案頭，event 時間點為手工滾動binlog的時間點 2018-10-04 15:31:55 ，這裡並未有任何變化。

mysqlbinlog: [Warning] unknown variable 'loose_default-character-set=utf8'
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#181004 15:31:55 server id 3306111 end_log_pos 123 CRC32 0x9cc61928 Start: binlog v 4, server v 5.7.20-log created 181004 15:31:55
# Warning: this binlog is either in use or was not closed properly.
BINLOG '
68G1Ww9/cjIAdwAAAHsAAAABAAQANS43LjIwLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
ASgZxpw=
'/*!*/;
# at 123
#181004 15:31:55 server id 3306111 end_log_pos 194 CRC32 0xc34422d7 Previous-GTIDs
# ec123678-5e26-11e7-9d38-000c295e08a0:182318-199336

（3）at 194 position，事務的第一個event，也就是用於記錄事務的GTID的event，時間點為 15:36:42 ，透過我們事務操作時記錄的時間資訊，該時間為執行commit語句的時間點 15:36:42 。

# at 194
#181004 15:36:42 server id 3306111 end_log_pos 259 CRC32 0x7971213c GTID last_committed=0   sequence_number=1   rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'ec123678-5e26-11e7-9d38-000c295e08a0:199337'/*!*/;

（4） at 259 position，事務的第二個event，也就是用於記錄事務的begin;語句的event，時間點為 15:35:21 ，透過我們事務操作時記錄的時間資訊，該時間為執行update語句的時間點 15:35:21 ，並不是執行begin;語句的時間點 15:33:02 ，說明該event是在執行update語句時產生，並不是在執行begin;語句時產生的。

#181004 15:35:21 server id 3306111 end_log_pos 338 CRC32 0x4d3af767 Query thread_id=3   exec_time=0 error_code=0
SET TIMESTAMP=1538638521/*!*/;
SET @@session.pseudo_thread_id=3/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1436549152/*!*/;
SET @@session.auto_increment_increment=2, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=83/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;

（5）at 338 position，事務的第三個event，用於記錄事務執行的原始SQL語句(需要啟用引數：binlog_rows_query_log_events=ON)，時間點仍然是執行update語句的時間點 (15:35:21) ，說明該event也是在執行update語句時產生。

# at 338
#181004 15:35:21 server id 3306111 end_log_pos 398 CRC32 0x066200c5 Rows_query
# update sbtest1 set k=k+1 where id=21

（6）at 398 position，事務的第四個event，用於記錄事務對應的操作表在記憶體中的對映ID，時間點仍然是執行update語句的時間點 (15:35:21) ，說明該event也是在執行update語句時產生。

# at 398
#181004 15:35:21 server id 3306111 end_log_pos 457 CRC32 0x020d3fcf Table_map: `sbtest`.`sbtest1` mapped to number 143

（7）at 457 position，事務的第五個event，用於記錄事務的完整操作語句和資料記錄，也就是真正在執行update語句做資料修改（時間點仍然是 15:35:21），說明該event也是在執行update語句時產生。

# at 457
#181004 15:35:21 server id 3306111 end_log_pos 761 CRC32 0xdcfd94ba Update_rows: table id 143 flags: STMT_END_F
BINLOG '
ucK1Wx1/cjIAPAAAAI4BAACAACR1cGRhdGUgc2J0ZXN0MSBzZXQgaz1rKzEgd2hlcmUgaWQ9MjHF
AGIG
ucK1WxN/cjIAOwAAAMkBAAAAAI8AAAAAAAEABnNidGVzdAAHc2J0ZXN0MQAEAwP+/gTuaP60AM8/
DQI=
ucK1Wx9/cjIAMAEAAPkCAAAAAI8AAAAAAAEAAgAE///wFQAAABXlJQB3ADA5Mjc5MjEwMjE5LTM3
NzQ1ODM5OTA4LTU2MTg1Njk5MzI3LTc5NDc3MTU4NjQxLTg2NzExMjQyOTU2LTYxNDQ5NTQwMzky
LTQyNjIyODA0NTA2LTYxMDMxNTEyODQ1LTM2NzE4NDIyODQwLTExMDI4ODAzODQ5A3h4ePAVAAAA
FuUlAHcAMDkyNzkyMTAyMTktMzc3NDU4Mzk5MDgtNTYxODU2OTkzMjctNzk0NzcxNTg2NDEtODY3
MTEyNDI5NTYtNjE0NDk1NDAzOTItNDI2MjI4MDQ1MDYtNjEwMzE1MTI4NDUtMzY3MTg0MjI4NDAt
MTEwMjg4MDM4NDkDeHh4upT93A==
'/*!*/;
### UPDATE `sbtest`.`sbtest1`
### WHERE
### @1=21 /* INT meta=0 nullable=0 is_null=0 */
### @2=2483477 /* INT meta=0 nullable=0 is_null=0 */
### @3='09279210219-37745839908-56185699327-79477158641-86711242956-61449540392-42622804506-61031512845-36718422840-11028803849' /* STRING(360) meta=61032 nullable=0 is_null=0 */
### @4='xxx' /* STRING(180) meta=65204 nullable=0 is_null=0 */
### SET
### @1=21 /* INT meta=0 nullable=0 is_null=0 */
### @2=2483478 /* INT meta=0 nullable=0 is_null=0 */
### @3='09279210219-37745839908-56185699327-79477158641-86711242956-61449540392-42622804506-61031512845-36718422840-11028803849' /* STRING(360) meta=61032 nullable=0 is_null=0 */
### @4='xxx' /* STRING(180) meta=65204 nullable=0 is_null=0 */

（8）at 761 position，事務的第六個event，用於記錄事務的commit語句，時間點為15:36:42，透過我們事務操作時記錄的時間資訊，該時間為執行commit語句的時間點15:36:42，說明該event是在執行commit語句時產生的。

# at 761
#181004 15:36:42 server id 3306111 end_log_pos 792 CRC32 0x3ad66423 Xid = 30
COMMIT/*!*/;
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

綜上所述，在上述binlog解析內容中，使用者事務的event有GTID(記錄事務GTID)、Query（記錄事務begin;語句）、Rows_query(在row格式下記錄事務原始SQL語句)、Table_map（記錄事務操作表在記憶體中的對映ID）、Update_rows（記錄事務真正操作的語句和修改的具體資料記錄）、xid（記錄事務commit；語句）幾種型別，其中：

（1）GTID和xid型別的event是在事務執行commit語句時產生的

（2）Query、Rows_query、Table_map、Update_rows 型別的event是在事務執行update 語句時產生的

（3）執行begin;語句時未產生任何event

本案例分析到此結束，留一個思考題給大家吧(大家可以依樣畫葫蘆)。如果是主從架構，那麼：

（1）從庫的relay log中的event時間點會不會與主庫binlog中記錄的相同事務（這裡指GTID相同）event時間點不同？

（2）從庫如果啟用了log_slave_updates=ON引數，從庫自身的binlog中記錄的複製事務的event會不會與主庫binlog中記錄的相同事務（這裡指GTID相同） event時間點不同？

（3）如果主庫存在併發事務，那麼主庫的binlog中記錄的event時間點又是怎樣的呢？

| 作者簡介

羅小波·沃趣科技高階資料庫技術專家

IT從業多年，主要負責MySQL 產品的資料庫支撐與售後二線支撐。曾參與版本釋出系統、輕量級監控系統、運維管理平臺、資料庫管理平臺的設計與編寫，熟悉MySQL體系結構，Innodb儲存引擎，喜好專研開源技術，多次在公開場合做過線下線上資料庫專題分享，發表過多篇資料庫相關的研究文章。

為何Binlog中同一個事務的event時間點會亂序？

驗證準備

驗證過程

相關文章