原创｜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函数？代码中主要有这几个地方：
- 执行一个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等。本公众号旨在推广和分享数据库领域专业知识，与广大数据库技术爱好者共同成长。