MySQL binlog 中的時間戳，你明白了嗎？

作者：鳥山明 2024-08-28 13:09:50

事務的執行順序與提交順序不同，而 binlog 中的記錄順序與事務的提交順序相同，因此導致主從事務的執行順序不同，從而出現數據不一致。

引言

MySQL 中的主從復制基于邏輯日志 binlog 實現，而 binlog 由多個 event 組成。每個 event 自帶時間戳，而主從延遲的計算正是基于該時間戳實現，因此 event 的時間戳很重要。本文測試并分析 binlog 不同模式下時間戳的區別。

概念

binlog_format

MySQL 中 binlog 有三種模式，包括：

statement-based logging（語句模式），記錄原始 SQL，缺點是可能導致數據不一致；
row-based logging（行模式），對于 DML，記錄每一行數據的變化，對于 DDL，記錄原始 SQL，也是默認值；
mixed logging（混合模式），優先使用語句模式，不滿足條件時切換為行模式，常見的不滿足條件的場景包括：

使用非確定性函數或語句，比如 UUID()、NOW()；

操作包含觸發器、存儲過程或用戶定義函數（UDF）。

需要注意的是可以設置的 binog 模式與事務隔離級別有關系。

If you are using InnoDB tables and the transaction isolation level is READ COMMITTED or READ UNCOMMITTED, only row-based logging can be used.

其中：

READ COMMITTED 與 READ UNCOMMITTED 中僅支持行模式，可以修改為語句模式，但執行 SQL 時會報錯。
不支持的原因是語句模式下這兩種事務隔離級別可能導致數據不一致。

參考文章為什么 MySQL 事務默認隔離級別是可重復讀？，其中假設兩個事務的執行順序見下表。

時間	事務 A	事務 B
1	begin;	begin;
2	delete from A where a < 10;
3		insert into A values(5);
4		commit;
5	commit;

binlog 中的記錄順序如下所示。

圖片

顯然，事務的執行順序與提交順序不同，而 binlog 中的記錄順序與事務的提交順序相同，因此導致主從事務的執行順序不同，從而出現數據不一致。

Event

本節參考《深入理解 MySQL 主從原理》。

每個事務的 binlog 由多個 Event 組成，每個 Event 的主要結構包括：

Event header

timestamp，保存語句開始執行的時間，正是本文重點關注的字段；

type_code，保存 Event 的類型；

server_id，保存生成 Event 的數據庫的 server_id；

event_len，保存整個 Event 的長度；

end_log_p，保存下一個 Event 的開始位置；

Event data，不同 type_code 對應不同的格式；
Event footer
crc，保存整個 Event 的 crc 校驗碼，用于標識 Event 的完整性。

如下所示，是語句模式下一段 binlog Event，其中紅框中都是 Event header。

圖片

常見的 Event 類型按照寫入文件的順序包括：

GTID_EVENT，其中攜帶 last commit 和 seq number 等信息；
QUERY_EVENT，語句模式下記錄實際的語句，行模式下 DML 不記錄實際的語句，DDL 是記錄的語句；
TABLE_MAP_EVENT，包含 table_id 和具體表名的映射關系；
WRITE_ROWS_EVENT，INSERT 語句生成的 Event，包括插入的實際數據，行模式中特有；
DELETE_ROWS_EVENT，DELETE 語句生成的 Event，包括實際要刪除的數據，行模式中特有；
UPDATE_ROWS_EVENT，UPDTE 語句生成的 Event，包括更新前后的數據，行模式中特有；
XID_EVENT，其中攜帶 XID 信息。

測試

測試環境

數據庫版本：5.7.24

事務隔離級別：RR

開始測試前指定提示符 prompt，從而將命令行的當前時間顯示在前面。

/export/servers/mysql/bin/mysql -uadmin -p3341 -h 127.0.0.1 -P 3341 -D test_zk --prompt='\r:\m:\s> '

注意顯示的時間與命令開始執行的時間會有偏差，原因是輸入命令需要時間，而顯示的時間是輸入命令的開始時間。

下面分別測試行模式與語句模式下隱式事務與顯式事務寫入 binlog 的區別。

行模式

隱式事務

08:27:31> update t3_bak set create_time=now() where id<1000000;
Query OK, 999989 rows affected (8.81 sec)
Rows matched: 999989  Changed: 999989  Warnings: 0

查看 binlog；

# at 194
#240813  8:27:32 server id 3341  end_log_pos 259 CRC32 0x8f3d5b01       GTID    last_committed=0        sequence_number=1       rbr_notallow=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'd16716c7-c94e-11ed-a186-fa163e19c3b7:67636'/*!*/;
# at 259
#240813  8:27:32 server id 3341  end_log_pos 342 CRC32 0x83532332       Query   thread_id=1250  exec_time=0     error_code=0
SET TIMESTAMP=1723508852/*!*/;
BEGIN
/*!*/;
# at 342
#240813  8:27:32 server id 3341  end_log_pos 418 CRC32 0xde6a90cd       Rows_query
# update t3_bak set create_time=now() where id<1000000
# at 418
#240813  8:27:32 server id 3341  end_log_pos 477 CRC32 0x3c9742c6       Table_map: `test_zk`.`t3_bak` mapped to number 2270
# at 477
#240813  8:27:32 server id 3341  end_log_pos 8649 CRC32 0x0a5f2233      Update_rows: table id 2270
# at 8649
#240813  8:27:32 server id 3341  end_log_pos 16825 CRC32 0x4a036014     Update_rows: table id 2270
...
# at 44194605
#240813  8:27:32 server id 3341  end_log_pos 44194636 CRC32 0xd524e4c2  Xid = 1520760
COMMIT/*!*/;

其中：

update 開始時間 08:27:32，執行用時 8.81 s，因此結束時間 08:27:40；
所有 event header timestamp 相同，均顯示 8:27:32，等于 update 的開始時間；
query event 顯示 exec_time=0；
SET TIMESTAMP=1723509136，用于保證主從執行環境一致；
行模式 binlog 中 Rows_query 記錄原始 SQL 的原因是開啟 binlog_rows_query_log_events 參數，用于將原始 SQL 作為注釋保存在 binlog 中，不會實際執行。

顯式事務

08:32:05> begin;
Query OK, 0 rows affected (0.00 sec)

08:32:15> update t3_bak set create_time=now() where id<1000000;
Query OK, 999989 rows affected (8.68 sec)
Rows matched: 999989  Changed: 999989  Warnings: 0

08:32:45> commit;
Query OK, 0 rows affected (0.21 sec)

binlog：

# at 194
#240813  8:32:46 server id 3341  end_log_pos 259 CRC32 0xd3661504       GTID    last_committed=0        sequence_number=1       rbr_notallow=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'd16716c7-c94e-11ed-a186-fa163e19c3b7:67637'/*!*/;
# at 259
#240813  8:32:16 server id 3341  end_log_pos 342 CRC32 0x99dba315       Query   thread_id=1250  exec_time=0     error_code=0
SET TIMESTAMP=1723509136/*!*/;
BEGIN
/*!*/;
# at 342
#240813  8:32:16 server id 3341  end_log_pos 418 CRC32 0x9138a9a5       Rows_query
# update t3_bak set create_time=now() where id<1000000
...
# at 44194605
#240813  8:32:46 server id 3341  end_log_pos 44194636 CRC32 0x892dfbf1  Xid = 1520766
COMMIT/*!*/;

其中：

update 開始時間 08:27:31，執行用時 8.81 s，因此結束時間 08:27:40；
GTID_event 與 XID_EVENT 的 timestamp 相同，等于 8:32:46，等于 commit 的開始執行時間；
Query event 與 Rows_query event 的 timestamp 相同，等于 8:32:16，等于 update 的開始執行時間；
begin 的 timestamp 等于 update 的開始時間，并不等于實際 begin 語句的實際實際執行時間，可以簡單認為 binlog 中的 BEGIN 與實際的 begin 命令無關；
顯然 binlog 中沒有保存執行 begin 命令的時間，當然執行 begin 語句以后執行具體 SQL 以前并沒有啟動事務。具體可以參考文章 MySQL 核心模塊揭秘 | 04 期 | 終于要啟動事務了；
query event 顯示 exec_time=0。

分析

到這里，可以提出以下三個問題：

為什么隱式事務中所有 event timestamp 等于 update 的開始時間，包括 XID_EVENT；
為什么顯式事務中 event timestamp 亂序；
為什么隱式事務與顯式事務中 query event 均顯示 exec_time=0。

下面分析原因。

首先是第一個問題，為什么隱式事務中所有 event timestamp 等于 update 的開始時間，包括 XID_EVENT。

原因是每條命令執行前獲取時間戳，通過函數 thd->set_time() 獲取，而這條語句生成的多個 event 的時間戳從語句繼承過來。

隱式事務中必然僅執行一條 SQL，因此所有 event timestamp 等于 update 的開始時間。

然后是第二個問題，為什么顯式事務中 event timestamp 亂序。

8:32:46 GTID
8:32:16 Query
8:32:16 Rows_query
8:32:46 XID

其中：

不同于隱式事務，顯式事務中執行 commit 命令，執行前同樣執行函數 thd->set_time()，從而影響到自己生成的 binlog event；
GTID_event 與 XID_EVENT 都是 commit 命令在事務提交階段生成的 Event，因此顯示 commit 的開始執行時間；
顯然 GTID_event 生成的晚但是寫入 binlog 文件早，原因是 GTID_event 是在事務提交階段中創建后直接寫入文件，沒有經過 binlog cache；
GTID_event 始終是事務的第一個 event，原因是 binlog 中需要提前知道 GTID 的具體信息，因此在提交時將其組裝在最前面。

最后是第三個問題，為什么隱式事務與顯式事務中 query event 均顯示 exec_time=0。

原因是：

QUERY_EVENT 中的 exec_time 只記錄更改第一條數據的執行用時，且一般看到的都是 begin 語句；
begin 的 exec_time 等于其后更改第一條數據的執行用時，原因是 begin 是在更改第一條數據后，寫入 binlog；
因此如果更改第一條數據的執行用時很短，就會顯示為 query event 中的 exec_time=0。當然假如 SQL 中包括 sleep，顯示 exec_time 不等于 0。

因此，對于行模式：

無法獲取到 SQL 的執行用時；
顯式事務的 Rows_query 與隱式事務的全部 event timestamp 等于 SQL 的開始執行時間。

可以得出以下兩點結論：

對于大事務，每條 SQL 計算主從延遲時由于 event timestamp 相同，從庫執行完成前主從延遲都將持續增加（對于單線程復制）；
對于長事務，GTID_event 與 XID_EVENT 比中間 event timestamp 要晚，因此主從延遲會出現跳點，顯示本不會出現的延遲。

語句模式

修改 binlog 模式；

set session binlog_format='statement';

隱式事務

18:12:31> update t3_bak set create_time=now() where id<1000000;
Query OK, 999989 rows affected (8.19 sec)
Rows matched: 999989  Changed: 999989  Warnings: 0

binlog；

# at 194
#240816 18:12:32 server id 3341  end_log_pos 259 CRC32 0x47293428       GTID    last_committed=0        sequence_number=1       rbr_notallow=no
SET @@SESSION.GTID_NEXT= 'd16716c7-c94e-11ed-a186-fa163e19c3b7:67648'/*!*/;
# at 259
#240816 18:12:32 server id 3341  end_log_pos 352 CRC32 0xf5dd67f7       Query   thread_id=1261  exec_time=8     error_code=0
BEGIN
/*!*/;
# at 352
#240816 18:12:32 server id 3341  end_log_pos 492 CRC32 0xc5d67750       Query   thread_id=1261  exec_time=8     error_code=0
use `test_zk`/*!*/;
SET TIMESTAMP=1723803152/*!*/;
update t3_bak set create_time=now() where id<1000000
/*!*/;
# at 492
#240816 18:12:32 server id 3341  end_log_pos 523 CRC32 0xe90b07a7       Xid = 1521788
COMMIT/*!*/;

其中：

update 開始時間 18:12:32，執行用時 8.19 s，因此結束時間 18:12:40；
所有 event timestamp 相同，均顯示 18:12:32，等于 update 的開始時間；
query event 顯示 exec_time=8，等于 BEGIN 后第一條語句的執行用時；
語句模式中事務中的每個 DML 語句都會記錄一個 exec_time。

查看 event，可以更清楚的看到事務的全部 event。

18:25:39> show binlog events in 'mysql-bin.000080';
+------------------+-----+----------------+-----------+-------------+-----------------------------------------------------------------------+
| Log_name         | Pos | Event_type     | Server_id | End_log_pos | Info                                                                  |
+------------------+-----+----------------+-----------+-------------+-----------------------------------------------------------------------+
| mysql-bin.000080 |   4 | Format_desc    |      3341 |         123 | Server ver: 5.7.24-log, Binlog ver: 4                                 |
| mysql-bin.000080 | 123 | Previous_gtids |      3341 |         194 | d16716c7-c94e-11ed-a186-fa163e19c3b7:1-67647                          |
| mysql-bin.000080 | 194 | Gtid           |      3341 |         259 | SET @@SESSION.GTID_NEXT= 'd16716c7-c94e-11ed-a186-fa163e19c3b7:67648' |
| mysql-bin.000080 | 259 | Query          |      3341 |         352 | BEGIN                                                                 |
| mysql-bin.000080 | 352 | Query          |      3341 |         492 | use `test_zk`; update t3_bak set create_time=now() where id<1000000   |
| mysql-bin.000080 | 492 | Xid            |      3341 |         523 | COMMIT /* xid=1521788 */                                              |
+------------------+-----+----------------+-----------+-------------+-----------------------------------------------------------------------+
6 rows in set (0.00 sec)

其中：

QUERY_EVENT 中顯示 info = BEGIN，可以簡單理解為自動加 BEGIN 語句。

顯式事務

19:16:49> begin;
Query OK, 0 rows affected (0.00 sec)

19:16:54> update t3_bak set create_time=now() where id<1000000;
Query OK, 999989 rows affected (8.47 sec)
Rows matched: 999989  Changed: 999989  Warnings: 0

19:17:19> commit;
Query OK, 0 rows affected (0.01 sec)

binlog；

# at 194
#240816 19:17:19 server id 3341  end_log_pos 259 CRC32 0x364ff2e2       GTID    last_committed=0        sequence_number=1       rbr_notallow=no
SET @@SESSION.GTID_NEXT= 'd16716c7-c94e-11ed-a186-fa163e19c3b7:67649'/*!*/;
# at 259
#240816 19:16:54 server id 3341  end_log_pos 352 CRC32 0x368c08f4       Query   thread_id=1261  exec_time=8     error_code=0
BEGIN
/*!*/;
# at 352
#240816 19:16:54 server id 3341  end_log_pos 492 CRC32 0x0450bba8       Query   thread_id=1261  exec_time=8     error_code=0
use `test_zk`/*!*/;
SET TIMESTAMP=1723807014/*!*/;
update t3_bak set create_time=now() where id<1000000
/*!*/;
# at 492
#240816 19:17:19 server id 3341  end_log_pos 523 CRC32 0xf75171f9       Xid = 1521794
COMMIT/*!*/;

其中：

update 開始時間 19:16:54，執行用時 8.47 s，因此結束時間 19:17:02；
GTID_event 與 XID_EVENT timestamp 相同，等于 19:17:19，等于 commit 的開始執行時間；
Query event 與 Rows_query event timestamp 相同，等于 19:16:54，等于 update 的開始執行時間；
BEGIN timestamp 等于 update 的開始時間，并不等于實際 begin 語句的實際實際執行時間；
query event 顯示 exec_time=8，等于 BEGIN 后第一條語句的執行用時。

對比

類型	exec_time	所有 event timestamp 相同
行模式 + 隱式事務	通常等于 0	是
行模式 + 顯式事務	通常等于 0	否
語句模式 + 隱式事務	等于事務中第一條 SQL 的執行用時	是
語句模式 + 顯式事務	等于事務中第一條 SQL 的執行用時	否

其中：

行模式中 QUERY_EVENT 中的 exec_time 通常等于 0，因此可以認為無效；
語句模式中 QUERY_EVENT 中的 exec_time 等于事務中第一條 SQL 的執行用時；
顯式事務中 commit 是單獨的命令，執行前獲取時間戳，因此與事務中其他 event 的時間戳不同。

結論

本文主要測試并介紹 binlog event header 的 timestamp 字段與 QUERY_EVENT 中的 exec_time 字段。

binlog event header 的 timestamp 字段中保存語句開始執行的時間，具體取值與是否使用顯式事務有關：

隱式事務，所有 event header timestamp 相同，均等于語句的開始執行時間；
顯式事務，GTID_event 與 XID_EVENT 的 timestamp 與其他 event 不同，原因是單獨執行 commit 命令時重新獲取時間戳。

QUERY_EVENT 中的 exec_time 字段中保存更改第一條數據的執行用時，具體取值與 binlog 的模式有關：

行模式，通常等于 0，原因是理論上更改一條數據很快；
語句模式，通常不等于 0，原因是等于 SQL 的執行用時（可能更新多行），且每個 DML 語句都會記錄一個 exec_time。

因此，對于行模式：

無法獲取到 SQL 的執行用時；
無法獲取到顯式事務中 begin 的執行時間。

此外可以發現 timestamp 對于大事務與長事務主從延遲的影響：

對于大事務，每條 SQL 計算主從延遲時由于 event timestamp 相同，從庫執行完成前主從延遲都將持續增加（對于單線程復制）；
對于長事務，GTID_event 與 XID_EVENT 比中間 event timestamp 要晚，因此主從延遲會出現跳點，顯示本不會出現的延遲。

具體將在下一篇文章中講解。

責任編輯：武曉燕來源：丹柿小院

MySQL 日志順序