「第一部分引言」

在日常运维MySQL的过程中，不知大家是否有留意到，有时会发现binlog中的时间并不是有序的，如果对这种情况感到疑惑，那么本文将能解答你的问题。

「第二部分时间来源」

每一个event实例都继承自Log_event类，在Log_event的构造函数中会设置event头部的时间：

Log_event::Log_event(THD *thd_arg, uint16 flags_arg,
                     enum_event_cache_type cache_type_arg,
                     enum_event_logging_type logging_type_arg,
                     Log_event_header *header, Log_event_footer *footer)
    : temp_buf(nullptr),
      m_free_temp_buf_in_destructor(true),
      exec_time(0),
      event_cache_type(cache_type_arg),
      event_logging_type(logging_type_arg),
      crc(0),
      common_header(header),
      common_footer(footer),
      thd(thd_arg) {
  server_id = thd->server_id;
  common_header->unmasked_server_id = server_id;
  common_header->when = thd->start_time;
  common_header->log_pos = 0;
  common_header->flags = flags_arg;
}

可以看到，event的时间的直接来源是当前thd句柄的start_time，那么这个start_time又是来自于哪里？THD类提供了一个set_time函数专门用来设置start_time：

void THD::set_time() {
  start_utime = my_micro_time();
  m_lock_usec = 0;
  if (user_time.tv_sec || user_time.tv_usec)
    start_time = user_time;
  else
    my_micro_time_to_timeval(start_utime, &start_time);
}

该函数还有另一个带参数的重载版本：

void set_time(const struct timeval *t) {
    user_time = *t;
    set_time();
}

从上述代码可以看到，如果有设置user_time，将会使用user_time作为start_time，否则使用当前时间作为start_time。那么在什么时候会调用THD::set_time函数？代码中主要有这几个地方：

执行一个sql语句，在语句开始执行前会调用无参数版本的THD::set_time（可以参考dispatch_command函数）
更新timestamp变量（set timestamp=xxx）会调用有参数版本的THD::set_time将THD::start_time和THD::user_time更新为指定值
slave回放某些event(Rows_log_event，Query_log_event)会调用有参数版本的THD::set_time将start_time设置为event头部所带的时间

「第三部分 binlog时间乱序原因」

这里我们只考虑master，不考虑slave和人为设置时间的情况。从前面的介绍可以知道，event时间对应的是sql语句的开始时间，如果一条语句执行了很久，这条语句记录到binlog中的时间仍然是语句开始的时间，在这期间如果有其它执行时间较短的事务写入binlog，就会出现binlog时间乱序的现象。我们通过一个实验来感受一下：

1、数据准备

2、开启会话1，执行操作

3、会话1阻塞后，立即开启会话2，执行操作

4、导出binlog，观察时间顺序

可以看到binlog中的时间并不是有序的，另外注意到每个BEGIN后面都有一个exec_time，这里的exec_time是语句的执行时间，就上图的情况而言，一个BEGIN真的执行了100s吗？实际上这里的begin和commit是提交的时候自动生成的，既然是自动生成的，那么它们的开始时间和THD::start_time也就是一样的，而exec_time是当前时间减去开始时间，exec_time=100也就符合预期了。这里特别说明一下，单独执行begin不会产生binlog，在事务第一次写入binlog到临时缓存的时候才会写入begin，commit是在事务提交时产生的，begin和commit的时间没有必然联系。

「第四部分 rotate」

执行时间较长的事务，除了影响它自身的binlog event的时间，还可能影响其它event的时间。这种情况需要满足：

该事务提交的时候，所在线程在组提交的commit阶段是leader线程
该组事务提交完成后binlog文件大小超过了设定的最大值

这两个条件满足后，leader线程会对binlog进行rotate操作，旧的binlog需要写入Rotate_log_event，新生成的binlog文件会写入Format_description_log_event，构造这些event的过程中并不会设置头部的时间，所以头部的时间一直都是0，写入到文件的时间来自于Log_event::get_time函数：

time_t Log_event::get_time() {
  /* Not previously initialized */
  if (!common_header->when.tv_sec && !common_header->when.tv_usec) {
    THD *tmp_thd = thd ? thd : current_thd;
    if (tmp_thd)
      common_header->when = tmp_thd->start_time;
    else
      my_micro_time_to_timeval(my_micro_time(), &(common_header->when));
  }
  return (time_t)common_header->when.tv_sec;
}

可以看到，当common_header中的时间为0时会自动将时间设置为当前线程的start_time，因此，当前binlog尾部的Rotate_log_event以及下一个binlog文件头部的Format_description_log_event, Previous_gtid_log_event都受到了影响。下面的例子可以演示这种情况：

1、数据准备

这里我们将binlog最大文件大小设置为4096，以便rotate发生。

2、复制以下语句到会话窗口

select now();
insert into t1 values(sleep(100),repeat('a',5000));
select now();
insert into t1 values(1,'a');
select now();

其中语句2执行完成后导致binlog rotate，由于只有一个线程，所以它一定是组提交所有阶段的leader。

3、导出第二个binlog，观察头部event的时间

下一个binlog文件头部两个event的时间和语句2开始执行的时间是一样的，符合我们前面所说的情况。

「第五部分总结」

本文简单介绍了binlog中时间的来源，解释了binlog中时间不一定有序的原因，感兴趣的读者可以自行学习binlog相关的代码。

腾讯数据库研发部数据库技术团队对内支持微信支付、微信红包、腾讯广告、腾讯音乐等公司自研业务，对外在腾讯云上支持 TencentDB 相关产品，如 CynosDB、CDB、TDSQL等。本公众号旨在推广和分享数据库领域专业知识，与广大数据库技术爱好者共同成长。

MySQL binlog时间异常分析相关推荐

mysql binlog生成异常_mysql binlog故障演练
mysql备份恢复 mysqldump备份企业故障恢复案例: 正在运行的网站系统 mysql数据库数据量25G,日业务量10-15M 备份策略: 每天晚上23点通过计划任务调用mysqldump执 ...
10分钟搭建MySQL Binlog分析+可视化方案
日志服务最近在原有 30+ 种数据采集渠道基础上,新增 MySQL Binlog.MySQL select 等数据库方案,仍然主打快捷.实时.稳定.所见即所得的特点. 以下我们以用户登录数据库作为案 ...
mysql binlog 回退_MYSQL Binglog分析利器:binlog2sql使用详解
大部分使用mysql的业务也都会开启binlog,用以记录数据库的更新操作.当然binlog的格式大家也都比较清楚,分别是statement.mixed.row模式.针对row格式的binlog,它以 ...
MySQL Binlog三种格式介绍及分析
一．Mysql Binlog格式介绍 Mysql binlog日志有三种格式,分别为Statement,MiXED,以及ROW! 1.Statement:每一条会修改数据的sql都会记录在binlog ...
mysql binlog mixed_MySQL Binlog三种格式介绍及分析
MySQL binlog日志有三种格式,分别为Statement,MiXED,以及ROW! 1.Statement:每一条会修改数据的sql都会记录在binlog中. 优点:不需要记录每一行的变化, ...
MySQL运维案例分析：Binlog中的时间戳
引言:本文从一个典型的案例入手来讲述Binlog中时间戳的原理和实践,通过本文你可以了解时间戳在Binlog中的作用及产生方法,以便在出现一些这方面怪异的问题时,做到心中有数,胸有成竹. 本文选自&l ...
mysql字段时间类型报异常Data truncation: Incorrect datetime value: ‘2099-01-01 00:00:00‘ for column
更新某日期字段报如下异常: ### Cause: com.mysql.cj.jdbc.exceptions.MysqlDataTruncation: Data truncation: Incorrec ...
使用python 模仿mybinlog 命令二进制分析mysql binlog
出处:黑洞中的奇点的博客 http://www.cnblogs.com/kelvin19840813/ 您的支持是对博主最大的鼓励,感谢您的认真阅读.本文版权归作者所有,欢迎转载,但请保留该声明. ...
mysql binlog协议_mysql binlog协议分析--具体event
这几天在修改canal, 连接mysql和maria接收到的event有所区别拿一个简单的insert sql来举例 mysql 会有以下几个event写入到binlog里 1.ANONYMOUS_ ...
MySQL Binlog解析
概述 MySQL的安装可以参考:Linux(CentOS)中常用软件安装,使用及异常--MySQL, VmTools MySQL关于Binlog的官方文档:The Binary Log 基于Binlo ...

MySQL binlog时间异常分析

「第一部分引言」

「第二部分时间来源」

「第三部分 binlog时间乱序原因」

「第四部分 rotate」

「第五部分总结」

MySQL binlog时间异常分析相关推荐

最新文章

热门文章

MySQL binlog时间异常分析

「第一部分 引言」

「第二部分 时间来源」

「第三部分 binlog时间乱序原因」

「第四部分 rotate」

「第五部分 总结」

MySQL binlog时间异常分析相关推荐

最新文章

热门文章

「第一部分引言」

「第二部分时间来源」

「第五部分总结」