談?wù)凪ySQL 8.0 binlog中精準的時間戳

1、相關(guān)解釋

immediate_commit_timestamp：代表是當前數(shù)據(jù)庫提交的時間，從庫/主庫都分別代表其提交的時間。

original_commit_timestamp：代表主庫提交的時間，不管有多少級聯(lián)的從庫這個時間永遠是主庫提交事務(wù)時候的時間。當然在主庫上其就等于 immediate_commit_timestamp 的時間。

它們的生成時間都是在從 binlog cache 寫入到 binlog 文件的時候，生成 GTID event 的時候，也就是 commit 的 flush 階段，我們簡稱這個為 提交時間。

但是需要注意的是 MGR 中主庫的 original_commit_timestamp 和 immediate_commit_timestamp 生成稍有提前（group_replication_trans_before_commit），并不是這里說的提交時間。

2、生成流程

2.1 關(guān)于 thd->variables.original_commit_timestamp

因為 original_commit_timestamp 來自這個值，一般情況下其值都是 UNDEFINED_COMMIT_TIMESTAMP，但是從庫上這個值會在應(yīng)用 GTID event 的時候更改為主庫帶過來的 original_commit_timestamp，因為主庫 original_commit_timestamp 就是提交時間，因此從庫的 thd->variables.original_commit_timestamp 也就設(shè)置為了主庫的提交時間。

但是有一個例外，就是 5.7 向 8.0 同步的時候，因為沒有這個值因此會被設(shè)置為 0。如下：

# original_commit_timestamp=0 (1970-01-01 0800.000000 CST)
# immediate_commit_timestamp=1703237689977004 (2023-12-22 1749.977004 CST)

2.2 生成方式

這個其實比較簡單，就是在函數(shù) MYSQL_BIN_LOG::write_transaction 中生成的，大概為：

immediate_commit_timestamp = 獲取的當前時間
original_commit_timestamp = thd->variables.original_commit_timestamp
（前面描述了thd->variables.original_commit_timestamp主庫不會設(shè)置為特定的值，其為 UNDEFINED_COMMIT_TIMESTAMP）

如果 original_commit_timestamp 等于 UNDEFINED_COMMIT_TIMESTAMP，那么它就是主庫，應(yīng)該將設(shè)置
original_commit_timestamp = immediate_commit_timestamp，這樣主庫的 original_commit_timestamp 
和 immediate_commit_timestamp 就相同了

否則 original_commit_timestamp 有特定的值，那么就是從庫，因為這個值來自 
thd->variables.original_commit_timestamp，前面說了他是應(yīng)用 GTID event 的值。

2.3 相關(guān)警告

當發(fā)現(xiàn)從庫的提交時間還比主庫的提交時間更慢的時候，顯然這是不合適的，就會出現(xiàn)這個警告如下：

if(original_commit_timestamp>immediate_commit_timestamp&&
!thd->rli_slave->get_c_rli()->gtid_timestamps_warning_logged){//如果原始時間還在于了當前服務(wù)器的提交時間，這是常見的警告
LogErr(WARNING_LEVEL,ER_INVALID_REPLICATION_TIMESTAMPS);//則報警

這就是大家經(jīng)常遇到的警告。

Invalidreplicationtimestamps:originalcommittimestampismorerecentthanthe
immediatecommittimestamp.Thismaybeanissueifdelayedreplicationisactive.
Makesurethatservershavetheirclockssettothecorrecttime.Nofurther
messagewillbeemitteduntilaftertimestampsbecomevalidagain."

3、其運維中的意義

3.1 在延時從庫中的應(yīng)用

如果配置了延遲從庫，則使用的是 immediate_commit_timestamp 作為延遲從庫應(yīng)用 event 的計算標準，因為這里 event 來自 relay log，因此 immediate_commit_timestamp 是 IO 線程連接庫（A->B->C，C 為延遲從庫，則這里為B庫提交事務(wù)的時間）的事務(wù)提交時間，在函數(shù) sql_delay_event 中有如下計算方式：

sql_delay_end=ceil((static_cast(ev)
->immediate_commit_timestamp)/
1000000.00)+
sql_delay;

而對于不支持的延時從庫則計算為：

sql_delay_end=ev->common_header->when.tv_sec+
rli->mi->clock_diff_with_master+sql_delay;

對于 immediate_commit_timestamp 和 ev->common_header->when.tv_sec 是有很大區(qū)別的，后者為 binlog header 中 timestamp 的時間，其在整個復(fù)制鏈路中并不會改變，其幾乎為命令發(fā)起的時間，而不是事務(wù)提交的時間。我們以 A->B->C 為列，其中 C 為一個延遲從庫。

支持 immediate_commit_timestamp 的情況：C 的延遲計算是以B庫提交時刻的時間為計算標準的。也就是其延遲是 B 庫提交后多久 C 庫應(yīng)用。

不支持 immediate_commit_timestamp 的情況：C 的延遲計算是以 A 庫命令發(fā)起的時間為計算標準的。也就是其延遲是 A 庫命令發(fā)起后多久 C 庫應(yīng)用。

很顯然前者的計算方式更為靠譜。在延遲從庫在等待的時候其線程的狀態(tài)為：

WaitinguntilMASTER_DELAYsecondsaftermasterexecutedevent

3.2 主庫判定事務(wù)的提交時刻和語句發(fā)起時間

某些時候我們可能需要知道語句什么時候發(fā)起執(zhí)行的，什么時候提交完成的，這個時候我們考慮使用 immediate_commit_timestamp 和 event header 的 timestamp 進行對比。

對于自動提交的 DML 語句，則 GTID event header 的 timestamp 為語句發(fā)起的時間，而 GTID event 的 immediate_commit_timestamp 為事務(wù)提交的時間，如果差值太大，可能是遇到了鎖（MDL LOCK 或 row lock）之類的問題。如下圖：

?

對于非自動提交的事務(wù)，則 GTID event 的 immediate_commit_timestamp 為事務(wù)提交的時間，但是語句開始執(zhí)行的時間需要查看具體語句的 event 才可以，不能查看 GTID event header 的 timestamp，這是 commit 命令發(fā)起的時間，如下圖：

?

當然類似，還可以獲取從庫的 binlog 信息來比對主庫是什么時候發(fā)起語句的，什么時候提交事務(wù)的，從庫又是什么時候提交事務(wù)的。類似如下圖，這是我的一個從庫，我這里是一個自動提交的 DML 語句：

很明顯，主庫發(fā)起語句時間和主庫提交時間以及從庫提交時間都有一定的差值。

主庫發(fā)起語句時間：1209

主庫提交事務(wù)時間：1213

從庫提交事務(wù)時間：1259

3.3 更加精確的延遲

這部分你在官方文檔有說明，其中主要包含 3 個視圖：

ps.replication_applier_status_by_worker： SQL 線程或者 WORKER 執(zhí)行相關(guān)

ps.replication_connection_status： IO 線程相關(guān)

ps.replication_applier_status_by_coordinator： 協(xié)調(diào)線程相關(guān)

其中大部分和 timestamp 相關(guān)的字段的都是自解釋的，而在 ps.replication_applier_status_by_coordinator 和 ps.replication_applier_status_by_worker 中有兩類字段類似 XXX_BUFFER_TIMESTAMP，XXX_APPLY_TIMESTAMP 比如：

LAST_PROCESSED_TRANSACTION_END_BUFFER_TIMESTAMP： 表示協(xié)調(diào)線程將事務(wù)分發(fā)給 WORKER 線程的時間

LAST_APPLIED_TRANSACTION_END_APPLY_TIMESTAMP： 表示應(yīng)用完事務(wù)的時間

具體代碼中可以斷點在：

Relay_log_info::finished_processing

Relay_log_info::started_processing

上進行觀察，實際上是 Relay_log_info 中多了如下信息：

  /**
    Stores information on the last processed transaction or the transaction
    that is currently being processed.

    STS:
    - timestamps of the currently applying/last applied transaction

    MTS:
    - coordinator thread: timestamps of the currently scheduling/last scheduled
      transaction in a worker's queue
    - worker thread: timestamps of the currently applying/last applied
      transaction
  */
  Gtid_monitoring_info *gtid_monitoring_info;

每個 WORKER 和協(xié)調(diào)線程都包含了這樣一個事務(wù)的監(jiān)控信息，因此可以在視圖中打印出來。

顯然我們就可以通過各種從庫中執(zhí)行的 timestamp 的時間和主庫提交時間也就是 ORIGINAL_COMMIT_TIMESTAMP 計算出來精確的延遲。

審核編輯：劉清