自拍偷在线精品自拍偷,亚洲欧美中文日韩v在线观看不卡

MySQL binlog 中的時(shí)間戳，你明白了嗎？

作者：鳥(niǎo)山明
數(shù)據(jù)庫(kù) MySQL
事務(wù)的執(zhí)行順序與提交順序不同，而 binlog 中的記錄順序與事務(wù)的提交順序相同，因此導(dǎo)致主從事務(wù)的執(zhí)行順序不同，從而出現(xiàn)數(shù)據(jù)不一致。

引言

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

概念

binlog_format

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

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

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

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

需要注意的是可以設(shè)置的 binog 模式與事務(wù)隔離級(jí)別有關(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 中僅支持行模式，可以修改為語(yǔ)句模式，但執(zhí)行 SQL 時(shí)會(huì)報(bào)錯(cuò)。
  • 不支持的原因是語(yǔ)句模式下這兩種事務(wù)隔離級(jí)別可能導(dǎo)致數(shù)據(jù)不一致。

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

時(shí)間

事務(wù) A

事務(wù) B

1

begin;

begin;

2

delete from A where a < 10;


3


insert into A values(5);

4


commit;

5

commit;


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

圖片圖片

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

Event

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

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

  • Event header

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

type_code，保存 Event 的類(lèi)型；

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

event_len，保存整個(gè) Event 的長(zhǎng)度；

end_log_p，保存下一個(gè) Event 的開(kāi)始位置；

  • Event data，不同 type_code 對(duì)應(yīng)不同的格式；
  • Event footer

  • crc，保存整個(gè) Event 的 crc 校驗(yàn)碼，用于標(biāo)識(shí) Event 的完整性。

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

圖片圖片

常見(jiàn)的 Event 類(lèi)型按照寫(xiě)入文件的順序包括：

  • GTID_EVENT，其中攜帶 last commit 和 seq number 等信息；
  • QUERY_EVENT，語(yǔ)句模式下記錄實(shí)際的語(yǔ)句，行模式下 DML 不記錄實(shí)際的語(yǔ)句，DDL 是記錄的語(yǔ)句；
  • TABLE_MAP_EVENT，包含 table_id 和具體表名的映射關(guān)系；
  • WRITE_ROWS_EVENT，INSERT 語(yǔ)句生成的 Event，包括插入的實(shí)際數(shù)據(jù)，行模式中特有；
  • DELETE_ROWS_EVENT，DELETE 語(yǔ)句生成的 Event，包括實(shí)際要?jiǎng)h除的數(shù)據(jù)，行模式中特有；
  • UPDATE_ROWS_EVENT，UPDTE 語(yǔ)句生成的 Event，包括更新前后的數(shù)據(jù)，行模式中特有；
  • XID_EVENT，其中攜帶 XID 信息。

測(cè)試

測(cè)試環(huán)境

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

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

開(kāi)始測(cè)試前指定提示符 prompt，從而將命令行的當(dāng)前時(shí)間顯示在前面。

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

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

下面分別測(cè)試行模式與語(yǔ)句模式下隱式事務(wù)與顯式事務(wù)寫(xiě)入 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 開(kāi)始時(shí)間 08:27:32，執(zhí)行用時(shí) 8.81 s，因此結(jié)束時(shí)間 08:27:40；
  • 所有 event header timestamp 相同，均顯示 8:27:32，等于 update 的開(kāi)始時(shí)間；
  • query event 顯示 exec_time=0；
  • SET TIMESTAMP=1723509136，用于保證主從執(zhí)行環(huán)境一致；
  • 行模式 binlog 中 Rows_query 記錄原始 SQL 的原因是開(kāi)啟 binlog_rows_query_log_events 參數(shù)，用于將原始 SQL 作為注釋保存在 binlog 中，不會(huì)實(shí)際執(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 開(kāi)始時(shí)間 08:27:31，執(zhí)行用時(shí) 8.81 s，因此結(jié)束時(shí)間 08:27:40；
  • GTID_event 與 XID_EVENT 的 timestamp 相同，等于 8:32:46，等于 commit 的開(kāi)始執(zhí)行時(shí)間；
  • Query event 與 Rows_query event 的 timestamp 相同，等于 8:32:16，等于 update 的開(kāi)始執(zhí)行時(shí)間；
  • begin 的 timestamp 等于 update 的開(kāi)始時(shí)間，并不等于實(shí)際 begin 語(yǔ)句的實(shí)際實(shí)際執(zhí)行時(shí)間，可以簡(jiǎn)單認(rèn)為 binlog 中的 BEGIN 與實(shí)際的 begin 命令無(wú)關(guān)；
  • 顯然 binlog 中沒(méi)有保存執(zhí)行 begin 命令的時(shí)間，當(dāng)然執(zhí)行 begin 語(yǔ)句以后執(zhí)行具體 SQL 以前并沒(méi)有啟動(dòng)事務(wù)。具體可以參考文章 MySQL 核心模塊揭秘 | 04 期 | 終于要啟動(dòng)事務(wù)了；
  • query event 顯示 exec_time=0。

分析

到這里，可以提出以下三個(gè)問(wèn)題：

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

下面分析原因。

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

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

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

然后是第二個(gè)問(wèn)題，為什么顯式事務(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 的開(kāi)始執(zhí)行時(shí)間；
  • 顯然 GTID_event 生成的晚但是寫(xiě)入 binlog 文件早，原因是 GTID_event 是在事務(wù)提交階段中創(chuàng)建后直接寫(xiě)入文件，沒(méi)有經(jīng)過(guò) binlog cache；
  • GTID_event 始終是事務(wù)的第一個(gè) event，原因是 binlog 中需要提前知道 GTID 的具體信息，因此在提交時(shí)將其組裝在最前面。

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

原因是：

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

因此，對(duì)于行模式：

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

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

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

語(yǔ)句模式

修改 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 開(kāi)始時(shí)間 18:12:32，執(zhí)行用時(shí) 8.19 s，因此結(jié)束時(shí)間 18:12:40；
  • 所有 event timestamp 相同，均顯示 18:12:32，等于 update 的開(kāi)始時(shí)間；
  • query event 顯示 exec_time=8，等于 BEGIN 后第一條語(yǔ)句的執(zhí)行用時(shí)；
  • 語(yǔ)句模式中事務(wù)中的每個(gè) DML 語(yǔ)句都會(huì)記錄一個(gè) 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，可以簡(jiǎn)單理解為自動(dòng)加 BEGIN 語(yǔ)句。

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

對(duì)比

類(lèi)型

exec_time

所有 event timestamp 相同

行模式 + 隱式事務(wù)

通常等于 0

是

行模式 + 顯式事務(wù)

通常等于 0

否

語(yǔ)句模式 + 隱式事務(wù)

等于事務(wù)中第一條 SQL 的執(zhí)行用時(shí)

是

語(yǔ)句模式 + 顯式事務(wù)

等于事務(wù)中第一條 SQL 的執(zhí)行用時(shí)

否

其中：

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

結(jié)論

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

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

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

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

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

因此，對(duì)于行模式：

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

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

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

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

責(zé)任編輯：武曉燕 來(lái)源： 丹柿小院
MySQL日志順序
相關(guān)推薦

2023-11-06 07:37:01

函數(shù)式插槽React

2024-03-27 13:33:00

MySQLInnoDB事務(wù)

2022-07-27 08:31:28

SQL開(kāi)發(fā)控制

2022-04-07 11:15:22

PulseEventAPI函數(shù)

2022-12-30 08:35:00

2011-08-04 14:00:01

MySQL數(shù)據(jù)庫(kù)時(shí)間戳失序binlog

2024-02-04 00:00:00

@ValidSpring@Validated

2022-10-10 18:38:56

inert屬性鍵盤(pán)

2023-12-08 08:38:15

EventLoopAPI瀏覽器

2023-12-28 08:43:28

前端算法搜索

2024-01-08 20:05:32

2022-10-19 08:19:32

動(dòng)態(tài)基線預(yù)警

2023-06-09 07:18:03

開(kāi)源數(shù)據(jù)庫(kù)

2022-05-31 07:32:19

JDK8API工具

2023-06-14 08:15:34

算法合并操作Winner

2022-10-24 20:25:40

云原生SpringJava

2023-12-06 08:01:03

CSSPostCSS

2022-10-08 08:09:13

MGRGreatSQL事務(wù)

2023-01-02 23:58:03

2015-09-18 09:17:06

數(shù)據(jù)分析
點(diǎn)贊
收藏

51CTO技術(shù)棧公眾號(hào)