引言

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

概念

binlog_format

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

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

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

操作包含觸發(fā)器、存儲過程或用戶定義函數(shù)（UDF）。

需要注意的是可以設(shè)置的 binog 模式與事務(wù)隔離級別有關(guān)系。

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 中僅支持行模式，可以修改為語句模式，但執(zhí)行 SQL 時會報錯。
• 不支持的原因是語句模式下這兩種事務(wù)隔離級別可能導致數(shù)據(jù)不一致。

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

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

圖片

顯然，事務(wù)的執(zhí)行順序與提交順序不同，而 binlog 中的記錄順序與事務(wù)的提交順序相同，因此導致主從事務(wù)的執(zhí)行順序不同，從而出現(xiàn)數(shù)據(jù)不一致。

Event

本節(jié)參考《深入理解 MySQL 主從原理》。

每個事務(wù)的 binlog 由多個 Event 組成，每個 Event 的主要結(jié)構(gòu)包括：

• Event header

timestamp，保存語句開始執(zhí)行的時間，正是本文重點關(guān)注的字段；

type_code，保存 Event 的類型；

server_id，保存生成 Event 的數(shù)據(jù)庫的 server_id；

event_len，保存整個 Event 的長度；

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

• Event data，不同 type_code 對應(yīng)不同的格式；
• 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 和具體表名的映射關(guān)系；
• WRITE_ROWS_EVENT，INSERT 語句生成的 Event，包括插入的實際數(shù)據(jù)，行模式中特有；
• DELETE_ROWS_EVENT，DELETE 語句生成的 Event，包括實際要刪除的數(shù)據(jù)，行模式中特有；
• UPDATE_ROWS_EVENT，UPDTE 語句生成的 Event，包括更新前后的數(shù)據(jù)，行模式中特有；
• XID_EVENT，其中攜帶 XID 信息。

測試

測試環(huán)境

數(shù)據(jù)庫版本：5.7.24

事務(wù)隔離級別：RR

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

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

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

下面分別測試行模式與語句模式下隱式事務(wù)與顯式事務(wù)寫入 binlog 的區(qū)別。

行模式

隱式事務(wù)

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，執(zhí)行用時 8.81 s，因此結(jié)束時間 08:27:40；
• 所有 event header timestamp 相同，均顯示 8:27:32，等于 update 的開始時間；
• query event 顯示 exec_time=0；
• SET TIMESTAMP=1723509136，用于保證主從執(zhí)行環(huán)境一致；
• 行模式 binlog 中 Rows_query 記錄原始 SQL 的原因是開啟 binlog_rows_query_log_events 參數(shù)，用于將原始 SQL 作為注釋保存在 binlog 中，不會實際執(zhí)行。

顯式事務(wù)

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

分析

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

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

下面分析原因。

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

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

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

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

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

其中：

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

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

原因是：

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

因此，對于行模式：

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

可以得出以下兩點結(jié)論：

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

語句模式

修改 binlog 模式；

set session binlog_format='statement';

隱式事務(wù)

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，執(zhí)行用時 8.19 s，因此結(jié)束時間 18:12:40；
• 所有 event timestamp 相同，均顯示 18:12:32，等于 update 的開始時間；
• query event 顯示 exec_time=8，等于 BEGIN 后第一條語句的執(zhí)行用時；
• 語句模式中事務(wù)中的每個 DML 語句都會記錄一個 exec_time。

查看 event，可以更清楚的看到事務(wù)的全部 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 語句。

顯式事務(wù)

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，執(zhí)行用時 8.47 s，因此結(jié)束時間 19:17:02；
• GTID_event 與 XID_EVENT timestamp 相同，等于 19:17:19，等于 commit 的開始執(zhí)行時間；
• Query event 與 Rows_query event timestamp 相同，等于 19:16:54，等于 update 的開始執(zhí)行時間；
• BEGIN timestamp 等于 update 的開始時間，并不等于實際 begin 語句的實際實際執(zhí)行時間；
• query event 顯示 exec_time=8，等于 BEGIN 后第一條語句的執(zhí)行用時。

對比

其中：

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

結(jié)論

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

binlog event header 的 timestamp 字段中保存語句開始執(zhí)行的時間，具體取值與是否使用顯式事務(wù)有關(guān)：

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

QUERY_EVENT 中的 exec_time 字段中保存更改第一條數(shù)據(jù)的執(zhí)行用時，具體取值與 binlog 的模式有關(guān)：

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

因此，對于行模式：

• 無法獲取到 SQL 的執(zhí)行用時；
• 無法獲取到顯式事務(wù)中 begin 的執(zhí)行時間。

此外可以發(fā)現(xiàn) timestamp 對于大事務(wù)與長事務(wù)主從延遲的影響：

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

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