MySQL binlog时间异常分析

「第一部分 引言」

在日常运维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函数？代码中主要有这几个地方：

1. 执行一个sql语句，在语句开始执行前会调用无参数版本的THD::set_time（可以参考dispatch_command函数）

2. 更新timestamp变量（set timestamp=xxx）会调用有参数版本的THD::set_time将THD::start_time和THD::user_time更新为指定值

3. 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的时间。这种情况需要满足：

1. 该事务提交的时候，所在线程在组提交的commit阶段是leader线程

2. 该组事务提交完成后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等。本公众号旨在推广和分享数据库领域专业知识，与广大数据库技术爱好者共同成长。