mysql binlog 时间 set_Binlog中的时间戳（上）

原创专栏｜周彦伟

去哪儿网数据库总监，目前还担任中国MySQL用户组(ACMUG)主席，领导和组织中国MySQL社区活动。

背景

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

#161213 10:11:35 server id 11766  end_log_pos 263690453 CRC32 0xbee3aaf5 Xid = 83631678

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

案例分析

先通过一个典型案例入手来讲述其中的细节，比如我们曾经在Galera Cluster碰到的一个问题，可以先看一段binlog内容：

#161213 10:11:35 server id 11766  end_log_pos 263677208 CRC32 0xbfc41688    GTID [commit=yes]

#161213 10:10:44 server id 11766  end_log_pos 263677291 CRC32 0x02537685    Query   thread_id=4901481   exec_time=0 error_code=0

#161213 10:10:44 server id 11766  end_log_pos 263677435 CRC32 0x0e70aab6    Write_rows: table id 17852 flags: STMT_END_F

#161213 10:10:44 server id 11766  end_log_pos 263677609 CRC32 0xb58d4c61    Update_rows: table id 17853 flags: STMT_END_F

#161213 10:11:35 server id 11766  end_log_pos 263690453 CRC32 0xbee3aaf5    Xid = 83631678

#161213 10:11:30 server id 11766  end_log_pos 263690501 CRC32 0x6e798470    GTID [commit=yes]

#161213 10:11:30 server id 11766  end_log_pos 263690592 CRC32 0x2b6a6d34    Query   thread_id=4900813   exec_time=5 error_code=0

#161213 10:11:30 server id 11766  end_log_pos 263691291 CRC32 0xc0f9ed87    Update_rows: table id 17891 flags: STMT_END_F

#161213 10:11:30 server id 11766  end_log_pos 263691322 CRC32 0xe40764c4    Xid = 83631679

#161213 10:11:35 server id 11766  end_log_pos 263691370 CRC32 0xbaa4ca30    GTID [commit=yes]

#161213 10:11:35 server id 11766  end_log_pos 263691453 CRC32 0x030f321c    Query   thread_id=4900813   exec_time=0 error_code=0

#161213 10:11:35 server id 11766  end_log_pos 263692240 CRC32 0x7584d6a1    Delete_rows: table id 73 flags: STMT_END_F

#161213 10:11:35 server id 11766  end_log_pos 263692271 CRC32 0x03abb120    Xid = 83631680

上面列出来的是被处理过的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在记录时间戳的问题上，是如何处理的。

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

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)

: is_valid_param(false), temp_buf(0), 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;

/* 这里就是用来在创建一个事件时，给这个事件的时间赋值的过程，

可以看到，这个时间的来源是thd->start_time的值，那我们需要

做的，就是弄清楚这个值的来源了 */

common_header->when= thd->start_time;

common_header->log_pos= 0;

common_header->flags= flags_arg;

}

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

bool dispatch_command(THD *thd, const COM_DATA *com_data,

enum enum_server_command command)

{

/* local variables... */

thd->set_command(command);

/*

Commands which always take a long time are logged into

the slow log only if opt_log_slow_admin_statements is set.

*/

thd->enable_slow_log= TRUE;

thd->lex->sql_command= SQLCOM_END; /* to avoid confusing VIEW detectors */

/* 就是在这里，初始化这个时间为当前时间 */

thd->set_time();

/* other code ... */

}

想必有些同学已经清楚了，其实Binlog事件中的时间戳是从语句那里继承过来的，一个语句产生多个事件，那这些事件的时间戳都是一样的，而且都是和第一个事件一致的(这点可以自己验证一下)。

那上面关于exec_time=5的问题，该怎么解释？我们再看一下代码：

Log_event(

thd_arg,

(thd_arg->thread_specific_used ? LOG_EVENT_THREAD_SPECIFIC_F :

0) |

(suppress_use ? LOG_EVENT_SUPPRESS_USE_F : 0),

using_trans ? Log_event::EVENT_TRANSACTIONAL_CACHE :

Log_event::EVENT_STMT_CACHE,

Log_event::EVENT_NORMAL_LOGGING,

header(), footer()),

data_buf(0)

{

/* local vaiables */

/* exec_time calculation has changed to use the same method that is used

to fill out "thd_arg->start_time" */

struct timeval end_time;

ulonglong micro_end_time= my_micro_time();

my_micro_time_to_timeval(micro_end_time, &end_time);

/* 时间的计算，是用当前时间(执行完成的时间)，减去thd_arg->start_time

的值，这个值我们上面已经见过，就是语句开始执行的时间，也就是说，exec_time

指的就是语句从开始到结束所用的时间，即实际上的语句执行时间 */

exec_time= end_time.tv_sec - thd_arg->start_time.tv_sec;

/* other code ... */

}

那现在就可以去解释事务83631679为什么执行了5秒钟，但所有事件的时间都是10:11:30了。就是因为这个事务是自动提交的，只有一条语句并且执行了5秒钟，就是这么简单，仅此而已。

因为是自动提交的，所以这个事务只有一条语句，那么thd->set_time()也只会被设置一次，所以这个事务中所有的事件，都停留在了这个时间点上，所以就出现了上面的现象。

发散思维

可能有同学有疑惑了，即使一个事务只有一条语句，那也是有提交的啊。提交时间确实是在5秒之后做的，内部难道没有做这个问题的处理？那我们可以做一个实验，还是一个事务一个语句，但此时不是自动提交，而是一个事务开始之后，等待了5秒钟，然后再去手动提交，然后再看Binlog内容：

mysql> set autocommit=0;

Query OK, 0 rows affected (0.00 sec)

mysql> insert into my1 values(13143306,'zhufeng');select sleep(5);commit;

Query OK, 1 row affected, 0 warning (0.00 sec)

+----------+

| sleep(5) |

+----------+

|        0 |

+----------+

1 row in set (5.00 sec)

Query OK, 0 rows affected (0.01 sec)

为了没有时间误差，上面的三条语句是同时执行的，中间做了5秒的等待操作，我们现在看一下对应的Binlog内容：

#161216 12:53:25 server id 23932  end_log_pos 449 CRC32 0x2939a45b     GTID [commit=yes]

#161216 12:53:20 server id 23932  end_log_pos 522 CRC32 0x1df41360     Query    thread_id=21    exec_time=    error_code=0

#161216 12:53:20 server id 23932  end_log_pos 614 CRC32 0xf1515ed0     Write_rows: table id 78 flags: STMT_END_F

#161216 12:53:25 server id 23932  end_log_pos 645 CRC32 0x69c2d142     Xid = 29321

此时很明显的看到了，事务的Xid及GTID两个提交事件的时间，都比执行插入的时间晚5秒钟。这正是因为，我们所执行的Commit语句与INSERT语句一样，都是一条语句，在执行前都会执行thd->set_time()，从而影响了自己生成的Binlog事件。

事务中事件顺序

上面我们已经了解过了，一个事务中，会有事务开始的事件，也会有事务提交的事件，也会有真正做事的事件，比如Write_rows等，它们之间的顺序，会与时间戳有一点关系。细心的同学可能已经发现，我们上一小节中举的例子，GTID在最前面，它的时间是12:53:25，而Write_rows在中间，但它的时间是12:53:20，这之间有什么关系么？

其实这个在之前介绍MySQL5.7多线程复制原理的时候已经讲过，在MySQL事务提交时，做的操作有三部分：

根据执行后的上下文环境，生成一个GTID事件。

组装事务产生的GTID。

提交到各种存储引擎。

从上面所做的事情可以看到，GTID信息其实是在提交时生成的。这一点在MySQL5.7中会更加明确，因为还需要我们已经熟知的last_committed及sequence_number(具体请参考关于MySQL5.7多线程复制原理一节)。那这也就可以解释，为什么GTID这个事件对应的时间和Xid是一样的了，就是因为它的时间是从Commit语句那里继承过来的。当然Xid也是同样的道理了，因为它们是同一个语句产生的两个不同事件。

但关于顺序问题，是与GTID这个事件的作用有关的。在MySQL Binlog中，必须要提前知道它已获取其具体信息，所以在MySQL提交并组装对应的Binlog时将其放到了最前面，从而导致了我们目前看到的关于时间问题的现象。

问题的延伸

待续......

本文节选自《MySQL运维内参》一书，更多内容请【阅读原文】或关注：