原创｜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等。本公众号旨在推广和分享数据库领域专业知识，与广大数据库技术爱好者共同成长。