源码分析 | 详解 binlog 时间戳与 exec_time 的关系

爱可生开源社区

发布于 2024-05-20 16:47:08

1370

发布于 2024-05-20 16:47:08

文章被收录于专栏：爱可生开源社区

作者：李锡超，苏商银行DBA，负责数据库和中间件运维和建设。擅长 MySQL、Python、Oracle，爱好骑行、技术研究和分享。

爱可生开源社区出品，原创内容未经授权不得随意使用，转载请联系小编并注明来源。

本文约 2000 字，预计阅读需要 8 分钟。

1概述

近期，某系统进行测试时，发现主从同步存在延迟，随即通过 binlog 确认延迟原因。当使用 mysqlbinlog 命令解析后，发现其中的信息“似懂非懂”。

例如，对于如下 binlog 片段：

# at 449880
#240430 18:38:49 server id 345  end_log_pos 449967 CRC32 0xb3e8a02a     GTID    last_committed=13       sequence_number=14      rbr_only=yes    original_committed_timestamp=1714473533138376   immediate_commit_timestamp=1714473539246294     transaction_length=446792
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
# original_commit_timestamp=1714473533138376 (2024-04-30 18:38:53.138376 CST)
# immediate_commit_timestamp=1714473539246294 (2024-04-30 18:38:59.246294 CST)
/*!80001 SET @@session.original_commit_timestamp=1714473533138376*//*!*/;
/*!80014 SET @@session.original_server_version=80027*//*!*/;
/*!80014 SET @@session.immediate_server_version=80027*//*!*/;
SET @@SESSION.GTID_NEXT= 'c0ac4587-6046-11ee-9fa7-001c42c92a7b:44'/*!*/;
# at 449967
#240430 18:38:16 server id 345  end_log_pos 450039 CRC32 0x0c7cb74e     Query   thread_id=16    exec_time=37    error_code=0
SET TIMESTAMP=1714473496/*!*/;
BEGIN
/*!*/;
/*!*/;
# at 450039
#240430 18:38:16 server id 345  end_log_pos 450098 CRC32 0xf9a84808     Table_map: `testdb`.`tb3` mapped to number 110
# at 450098
#240430 18:38:16 server id 345  end_log_pos 458309 CRC32 0xad84e9b0     Write_rows: table id 110
...
# at 896439
#240430 18:38:46 server id 345  end_log_pos 896498 CRC32 0x5cd7cd3b     Table_map: `testdb`.`tb3` mapped to number 110
# at 896498
#240430 18:38:46 server id 345  end_log_pos 896540 CRC32 0x21b77031     Write_rows: table id 110 flags: STMT_END_F
...
### INSERT INTO `testdb`.`tb3`
### SET
###   @1=131060 /* INT meta=0 nullable=0 is_null=0 */
###   @2='c' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
# at 896540
#240430 18:38:49 server id 345  end_log_pos 896599 CRC32 0x6d6bf911     Table_map: `testdb`.`tb3` mapped to number 110
# at 896599
#240430 18:38:49 server id 345  end_log_pos 896641 CRC32 0xccd2fbb1     Write_rows: table id 110 flags: STMT_END_F
...
### INSERT INTO `testdb`.`tb3`
### SET
###   @1=131061 /* INT meta=0 nullable=0 is_null=0 */
###   @2='c' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
# at 896641
#240430 18:38:49 server id 345  end_log_pos 896672 CRC32 0xadb14b9d     Xid = 85

通过以上 binlog 可知（P1）：

#240430 18:38:16 执行 begin 开启了事务  （为便于表述，将时间字段名为timestamp）
#240430 18:38:16 执行了 tb3的insert 操作
#240430 18:38:46 执行了 tb3的insert 操作
#240430 18:38:49 执行了 tb3的insert 操作
#240430 18:38:49 执行了commit操作

此外（P2）：

original_commit_timestamp=2024-04-30 18:38:53
immediate_commit_timestamp=2024-04-30 18:38:59
exec_time=37

针对 P2 信息，提出如下问题：

Q1：P2 中的字段分别表示什么意思？是如何计算的？
Q2：P2 的字段和 P1 看到的 timestamp 有什么关系呢？
Q4：P1 中的 timestamp 是如何取值的？特别是主从环境下

为此，通过测试验证，并结合源码分析 binlog 中常见 Event 时间与 exec_time 的由来，并总结字段之间的关系。

以下分析基于 MySQL 8.0，不同版本字段可能不同。

2主节点 binlog 日志

1. GTID Event

timestamp

对于主节点：如没有特殊说明，Event 的 timestamp 是在每个线程执行 dispatch_command() 初始位置获取最新时间戳（thd->start_time），并在生产 Event 对象时将 thd->start_time 赋值到 Log_event::common_header->when。

主要堆栈信息如下：

|-handle_connection (./sql/conn_handler/connection_handler_per_thread.cc:302)
  |-do_command (./sql/sql_parse.cc:1343)
    |-dispatch_command (./sql/sql_parse.cc:1922)
      // 设置 thd->start_time
      |-thd->set_time()
        |-my_micro_time_to_timeval(start_utime, &start_time)
      |-dispatch_sql_command (./sql/sql_parse.cc:5135)
        |-mysql_execute_command (./sql/sql_parse.cc:3518)
          |-Sql_cmd_dml::execute (./sql/sql_select.cc:579)
          ……
                        |-Table_map_log_event the_event(this, table, table->s->table_map_id,is_transactional)
                        ……
                          |-Rows_log_event *const ev = new RowsEventT(this, table, table->s->table_map_id, )
                          ……
                  |-Xid_log_event end_evt(thd, xid)

immediate_commit_timestamp/original_commit_timestamp

immediate_commit_timestamp 获取即为提交时刻的时间戳，主节点 original_commit_timestamp 等于 immediate_commit_timestamp。

|-error = trx_cache.flush(thd, &trx_bytes, wrote_xid)
  |-Transaction_ctx *trn_ctx = thd->get_transaction()
  |-trn_ctx->sequence_number = mysql_bin_log.m_dependency_tracker.step()
  |-if (trn_ctx->last_committed == SEQ_UNINIT): trn_ctx->last_committed = trn_ctx->sequence_number - 1
  |-if (!error): if ((error = mysql_bin_log.write_transaction(thd, this, &writer)))
    |-int64 sequence_number, last_committed
|-m_dependency_tracker.get_dependency(thd, sequence_number, last_committed)
|-thd->get_transaction()->last_committed = SEQ_UNINIT
    |-ulonglong immediate_commit_timestamp = my_micro_time()
    //|-ulonglong original_commit_timestamp = thd->variables.original_commit_timestamp
    |-ulonglong original_commit_timestamp = immediate_commit_timestamp
    |-uint32_t trx_immediate_server_version = do_server_version_int(::server_version)
    |-Gtid_log_event gtid_event(thd, cache_data->is_trx_cache(), last_committed, sequence_number,
        cache_data->may_have_sbr_stmts(), original_commit_timestamp,
        immediate_commit_timestamp, trx_original_server_version,
        trx_immediate_server_version)

2. BEGIN Event

timestamp

注意：对于主节点 BEGIN event 的 timestamp 并不是执行 BEGIN 时的时间戳，而是执行第一个修改操作。在完成 InnoDB 层第一行数据修改之后，生成并写入 Table_map event。在生成 Table_map event 之前，如果此时整个事务的 binlog 缓存是空的，才会立即获取该操作的 thd->start_time，并生成真正的 BEGIN event。

exec_time

同时，对于主节点的 exec_time 就是在生成 BEGIN Event 的过程中，获取最新的时间戳 - BEGIN Event 的 timestamp 而得。

exec_time = A - B

A：执行第一个修改 SQL，完成第一行修改（write/update/delete）操作后，生成 BEGIN Event 的时间。
B：第一个修改 SQL 的开始执行时间（thd->start_time）

内部堆栈与执行顺序如下：

3. Table_map Event

4. Write Event

5. Xid Event

6. 主节点小结

除了 BEGIN Event 的 timestamp 是第一个需要写入 binlog 操作（如：write/update/delete）的开始时间；
其它 Event 的 timestamp 为 SQL 语句执行时的开始时间；
immediate_commit_timestamp/original_commit_timestamp 即为提交时的时间戳；
exec_time = A - B
- A：执行第一个修改 SQL，完成第一行修改（write/update/delete）操作后，生成 BEGIN Event 的时间。
- B：第一个修改 SQL 的开始执行时间（thd->start_time）

3从节点 binlog 日志

1. GTID Event

timestamp

在从节点：对于 GTID Event，MySQL 在解析 Event 时，并不会获取主节点 GTID/XID Event 的时间戳，因此会“继承”该事务上一个操作的时间戳。而从节点所有修改操作的时间戳都来自于主节点执行操作时的时间戳。因此从节点的 GTID/XID Event 的时间即为主节点最后一个修改操作的 timestamp。

immediate_commit_timestamp/original_commit_timestamp

immediate_commit_timestamp 获取从节点提交时刻的时间戳。original_commit_timestamp 从 GTID Event 中的 original_commit_timestamp 获取，即为主节点提交操作的 timestamp。

主要堆栈信息如下：

|-handle_slave_worker (./sql/rpl_replica.cc:5891)
  |-slave_worker_exec_job_group (./sql/rpl_rli_pdb.cc:2549)
    |-Slave_worker::slave_worker_exec_event (./sql/rpl_rli_pdb.cc:1760)
      |-Xid_apply_log_event::do_apply_event_worker (./sql/log_event.cc:6179)
        |-Xid_log_event::do_commit (./sql/log_event.cc:6084)
          |-trans_commit (./sql/transaction.cc:246)
            |-ha_commit_trans (./sql/handler.cc:1765)
              |-MYSQL_BIN_LOG::commit (./sql/binlog.cc:8170)
                |-MYSQL_BIN_LOG::ordered_commit (./sql/binlog.cc:8789)
                  |-MYSQL_BIN_LOG::process_flush_stage_queue (./sql/binlog.cc:8326)
                    |-MYSQL_BIN_LOG::flush_thread_caches (./sql/binlog.cc:8218)
                      |-binlog_cache_mngr::flush (./sql/binlog.cc:1099)
                        |-binlog_cache_data::flush (./sql/binlog.cc:2098)
                          |-MYSQL_BIN_LOG::write_transaction (./sql/binlog.cc:1586)
                            // 生成并写入 GTID event
                            |-ulonglong immediate_commit_timestamp = my_micro_time()
                            |-if (original_commit_timestamp == UNDEFINED_COMMIT_TIMESTAMP){...}
                            |-Gtid_log_event gtid_event(thd, cache_data->is_trx_cache(), last_committed, sequence_number,
                               cache_data->may_have_sbr_stmts(), original_commit_timestamp, immediate_commit_timestamp, trx_original_server_version,
                               trx_immediate_server_version)

公式

immediate_commit_timestamp - original_commit_timestamp = A + B + C

A = 主节点 传输 binlog 到 从节点 的耗时
B = 从节点 重放 binlog 的耗时
C = 同步延迟/中断的耗时

2. BEGIN Event

timestamp

这里的 timestamp 来自于主节点 BEGIN Event 的 timestamp。其实际执行时，是会获取 BEGIN Event 的 timestamp 将其赋值给 thd->start_time/thd->user_time。从节点生成 Event 对象时，继续从 thd->start_time 获取时间戳即可。

exec_time

然后，从节点的 exec_time 依然是生成 BEGIN Event 的过程中，获取最新的时间戳 - timestamp 而得到（注意这里的 timestamp 来自于主节点修改 SQL 的开始执行时间）。

主要堆栈信息如下：

|-handle_slave_worker (./sql/rpl_replica.cc:5891)
  |-slave_worker_exec_job_group (./sql/rpl_rli_pdb.cc:2549)
    |-Slave_worker::slave_worker_exec_event (./sql/rpl_rli_pdb.cc:1760)
      |-Log_event::do_apply_event_worker (./sql/log_event.cc:1083)
        |-Query_log_event::do_apply_event (./sql/log_event.cc:4443)
          |-Query_log_event::do_apply_event (./sql/log_event.cc:4606)
            // 设置 user_time=start_time=ev.common_header->when
            |-thd->set_time(&(common_header->when))
            // query_arg="BEGIN"
            |-thd->set_query(query_arg, q_len_arg)
            ...

公式

exec_time = A + B + C + D

A = 主节点 整个事务的耗时
B = binlog 传输耗时
C = 同步延迟/中断耗时（可能-主要）
D = 从节点完成第一行数据修改

original_commit_timestamp - begin event 的 timestamp = 表示主节点整个事务的实际耗时（【主-第一个修改】到【主- commit 开始】）。

3. Table_map Event

4. Write Event

5. Xid Event

6. 从节点小节

除了 GTID/XID Event，其它 Event 的时间戳均来自于主节点的 Event；
GTID/XID Event 的 timestamp 为主节点最后一个修改操作开始时间；
GTID Event 的 original_commit_timestamp 来自于主节点，immediate_commit_timestamp 为最新的时间戳；
exec_time = A - B
- A = 从节点 生成 BEGIN Event 的最新时间戳
- B = 主节点 执行第一个 DML 操作的开始时间