mysql查看log时间戳_MySQL运维案例分析：Binlog中的时间戳

原标题：MySQL运维案例分析：Binlog中的时间戳

背景

众所周知，在Binlog文件中，经常会看到关于事件的时间属性，出现的方式都是如下这样的。

我们清楚地知道，161213 10:11:35表示的就是时间值，但除此之外呢？还能知道它的什么信息呢？

案例分析

先从一个典型的案例入手来讲述其中的细节，比如曾经在Galera Cluster碰到的一个问题，可以先看一段Binlog内容，如下。

上面列出来的是被处理过的Binlog内容，其中包括三个事务，每个事务只列出了标志性的事件，比如事务开始的GTID事件、执行线程信息及提交事件等。出现的顺序，就是Binlog内容的顺序，这一点可以从Xid的连续性看出来。

在上面一段内容中，重点关注一下时间信息。每一个事务中的每一个事件都有时间属性，可以看到，第一个事务是在10:11:35时间点提交的，第三个事务也是在这个时间提交的。但中间一个事务，即Xid为83631679的事务，包括提交时间在内的所有事件时间，都是在10:11:30时间点发生的，比其他两个事务足足早出现了5秒钟！

很多同学看到这样的现象之后，可能会有以下的疑问。

在Binlog文件中，不是以提交顺序存储的么，前面提交的事务怎么会存储在后面的位置呢？

假设事务83631679的开始时间是10:11:30，那么至少它的提交事件，即GTID事件的时间是10:11:35吧？

事务83631679的执行时间是5秒钟，从exec_time=5可以看出来这个信息的出现，那么第二个问题就变得更加让人疑惑了。

这里能看出exec_time=5这样的信息，值得称赞，这是一个很重要的信息。因为现在明确地知道，事务83631679是在10:11:30开始的。那么，这个Query又执行了5秒钟，可以和事务提交时间10:11:35对得上。现在要明确的一点就是，事务是在10:11:35提交的，只不过在Binlog内容看到的是10:11:30，那就要弄清楚Binlog在记录时间戳的问题上，是如何处理的。

时间戳是一个事件的属性，但这个属性的来源是哪里，也就是说这个时间是什么时候记录下来的，可以看如下一段代码。

如代码中的解释，需要找到thd->start_time的来源。这个值的设置很容易就可以找到，在每一条语句执行前都会做一次，通过函数thd->set_time()来设置。其中一个很重要的MySQL语句，在入口处理函数中就调用了，可以简单看一下，如下。