运维首页 > 数据运维 > 源码分析 | 详解 binlog 时间戳与 exec_time 的关系

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

2024年 5月 15日 86.9k 0

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

作者：李锡超，苏商银行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

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

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

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

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）

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

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

3. Table_map Event

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

4. Write Event

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

5. Xid Event

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

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

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

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

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

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

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

4. Write Event

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

5. Xid Event

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

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 操作的开始时间

4结语

至此，关于 binlog 中的时间戳与 exec_time
已基本梳理完成，有兴趣的朋友可以回到文章开头，再看看 Q1-Q3 是否有了答案。

最后，建议读者朋友实际模拟几个案例，以便于更加深刻的理解相关字段，后续在利用 binlog 分析主从同步问题时，能更加得心应手。

以上信息仅供交流，作者水平有限，如有不足之处，欢迎在评论区交流。

本文关键字：#MySQL# #binlog# #源码#

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

故障分析 | 如何解决由触发器导致 MySQL 内存溢出？
故障分析 | 一则 MySQL 从节点 hung 死问题分析
新特性解读 | MySQL 8.0 支持对单个数据库设置只读
技术分享 | MySQL 授权表运维注意事项
技术分享 | 如何通过 binlog 定位大事务？
新特性解读 | MySQL 8.3 可以打标签的 GTID
故障分析 | MySQL 执行 Online DDL 操作报错空间不足？
技术分享 | 如何缩短 MySQL 物理备份恢复时间？

源码分析 | 详解 binlog 时间戳与 exec_time 的关系-14✨ Github：https://github.com/actiontech/sqle

📚 文档：https://actiontech.github.io/sqle-docs/

💻 官网：https://opensource.actionsky.com/sqle/

👥 微信群：请添加小助手加入 ActionOpenSource

🔗 商业支持：https://www.actionsky.com/sqle

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

竹子爱熊猫
数据运维
0 0

相关文章

Oracle如何使用授予和撤销权限的语法和示例
Awesome Project: 探索 MatrixOrigin 云原生分布式数据库
下载丨66页PDF，云和恩墨技术通讯（2024年7月刊）
社区版oceanbase安装
Oracle 导出CSV工具-sqluldr2
ETL数据集成丨快速将MySQL数据迁移至Doris数据库

发布评论

竹子爱熊猫

这个人很懒，什么都没有留下～

文章8367 评论0