原创专栏|周彦伟
去哪儿网数据库总监,目前还担任中国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运维内参》一书,更多内容请【阅读原文】或关注: