背景
众所周知,在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,这之间有什么关系么?
其实,这在之前介绍MySQL 5.7多线程复制原理的时候已经讲过,在MySQL事务提交时,做的操作有如下三部分。
· 根据执行后的上下文环境,生成一个GTID事件。
· 组装事务产生的GTID。
· 提交到各种存储引擎。
从上面所做的事情中可以看到,GTID信息其实是在提交时生成的。这一点在MySQL 5.7中会更加明确,因为还需要我们已经熟知的last_committed及sequence_number来构造GTID(具体请参考第15章)。这也就可以解释,为什么GTID这个事件对应的时间和Xid是一样的了,就是因为它的时间是从Commit语句那里继承过来的。当然,Xid也是同样的道理了,因为它们是同一个语句产生的两个不同事件。
但关于顺序问题,是与GTID这个事件的作用有关的。在MySQL Binlog中,必须要提前知道GTID的具体信息,所以在MySQL提交并组装对应的Binlog时将其放到了最前面,从而导致了目前看到的关于时间问题的现象。
问题延伸
再回过头来看一下,最开始等待5秒的案例如下。
#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
为何一个更新语句执行了5秒钟?当然,可能有以下两个原因。
· 这个语句对应的查询条件,是一个慢查询,扫描会花很长时间(5秒钟),结果只更新了一行(因为只有一个Update_rows事件),从而导致了上面的现象。
· 本身执行不慢,但在等其他事务或锁的执行操作时,等了5秒钟。
这两种原因都是有可能的,也都可以解释得通。确定是哪种原因导致问题的方法很简单,那就是查看慢查询日志文件,找到thread_id为4900813的慢查询,或者对应的表的慢查询,并且一定要在server_id为11766的实例上面(这一点每个人都知道,但有时候会被忽略掉)。如果找到了,那就是第一种原因;如果找不到,那就是第二种原因了。
找啊找,结果在那个时间段内,都没有慢查询。
不管什么原因,执行了5秒钟,肯定是慢查询,怎么能找不到呢?这里对于MySQL的慢查询记录要多说一点,锁等待的时间在这里是不计算在内的。所以,如果是第2种原因,那么慢查询就必然是查不到的,并且exec_time=5对这一点也很有说服力,因为执行时间的计算是从开始时间到结束时间的差值,和慢查询的计算方法不同,所以这也说明了这5秒钟时间都是在等待的。
那么问题来了,它在等谁呢?竟然能等5秒钟?想必有另一个事务,拿到了它想要的锁,并且拿到锁的时间肯定超过5秒钟,那就需要继续找了。此时已经知道,大事务有如下2种。
单条自动提交的语句,本身执行时间长(exec_time比较大)。
事务开始时间和结束时间的跨度长。
找ROW格式的Binlog,咱有利器啊!来看下面一段脚本,这段脚本也会出现在第42章中。
# vim summarize_binlogs.sh #!/bin/bash BINLOG_FILE="mysql-bin.000046" START_TIME="2015-06-28 8:45:00" STOP_TIME="2015-06-28 10:10:00" mysqlbinlog --base64-output=decode-rows -vv --start-datetime="${START_TIME}" --stop-datetime="${STOP_TIME}" ${BINLOG_FILE} | awk \ 'BEGIN {xid="null";s_type=""; stm="";endtm="";intsta=0;inttal=0;s_count=0;count=0;insert_count=0;update_count=0;delete_count=0;flag=0;bf=0;period=0;} \ { if (match($0, /^(BEGIN)/)) {bg=1;} \ if (match($0, /#.*server id/)) {if(bg==1){statm=substr($1,2,6)" "$2;cmd=sprintf("date -d \"%s\" +%%s", statm);cmd|getline intsta;close(cmd);bg=0;bf=1;}else if(bf==1){endtm=substr($1,2,6)" "$2;cmd=sprintf("date -d \"%s\" +%%s", endtm);cmd|getline inttal;close(cmd);}} \ if(match($0, /#.*Table_map:.*mapped to number/)) {printf "Timestamp : " $1 " " $2 " Table : " $(NF-4); flag=1} \ else if (match($0, /#.*Xid =.*/)) {xid=$(NF)} \ else if (match($0, /(### INSERT INTO .*..*)/)) {count=count+1;insert_count=insert_count+1;s_type="INSERT"; s_count=s_count+1;} \ else if (match($0, /(### UPDATE .*..*)/)) {count=count+1;update_count=update_count+1;s_type="UPDATE"; s_count=s_count+1;} \ else if (match($0, /(### DELETE FROM .*..*)/)) {count=count+1;delete_count=delete_count+1;s_type="DELETE"; s_count=s_count+1;} \ else if (match($0, /^(# at) /) && flag==1 && s_count>0) {print " Query Type : "s_type " " s_count " row(s) affected" ;s_type=""; s_count=0; } \ else if (match($0, /^(COMMIT)/)) {period=inttal-intsta;if(inttal==0){period=0};print "[Transaction total : " count " Insert(s) : " insert_count " Update(s) : " update_count " Delete(s) : " \ delete_count " Xid : "xid" period : "period" ] \n+----------------------+----------------------+----------------------+----------------------+"; \ count=0;insert_count=0;update_count=0; delete_count=0;s_type=""; s_count=0; flag=0;bf=0;bg=0;} } '
这段脚本可以帮我们很轻松地找到跨度比较长的事务,通过结果中的period列来表示。分析了period列的数据之后,结果如下。
zhufeng@zhufengmac:~$ cat sum|grep Transaction|awk '{if($19>0)print}' [Transaction total : 8 Insert(s) : 8 Update(s) : 0 Delete(s) : 0 Xid : 83631021 period : 1 ] [Transaction total : 15 Insert(s) : 10 Update(s) : 4 Delete(s) : 1 Xid : 83631137 period : 1 ] [Transaction total : 10 Insert(s) : 7 Update(s) : 3 Delete(s) : 0 Xid : 83631517 period : 1 ] [Transaction total : 3 Insert(s) : 3 Update(s) : 0 Delete(s) : 0 Xid : 83631658 period : 1 ] [Transaction total : 16 Insert(s) : 10 Update(s) : 6 Delete(s) : 0 Xid : 83631678 period : 51 ] [Transaction total : 12 Insert(s) : 9 Update(s) : 3 Delete(s) : 0 Xid : 83631829 period : 1 ] [Transaction total : 5 Insert(s) : 4 Update(s) : 1 Delete(s) : 0 Xid : 83632139 period : 1 ] [Transaction total : 3 Insert(s) : 3 Update(s) : 0 Delete(s) : 0 Xid : 83632172 period : 1 ] [Transaction total : 3 Insert(s) : 3 Update(s) : 0 Delete(s) : 0 Xid : 83632206 period : 1 ]
很快发现,Xid为83631678的事务,竟然长达51秒。然后打开对应的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 263685326 CRC32 0xc512e73c Write_rows: table id 566 flags: STMT_END_F #161213 10:11:35 server id 11766 end_log_pos 263685556 CRC32 0x805318e4 Write_rows: table id 566 flags: STMT_END_F #161213 10:11:35 server id 11766 end_log_pos 263690422 CRC32 0x4de989c8 Write_rows: table id 73 flags: STMT_END_F #161213 10:11:35 server id 11766 end_log_pos 263690453 CRC32 0xbee3aaf5 Xid = 83631678
发现什么了吗?这不是事务83631678么,是本章开始位置所展示出来的三个事务中的第一个?没错,正是它。
首先,关于GTID事件和Xid事件的时间问题,上面已经解释过了,这是提交语句的时间,所以都是10:11:35,先忽略它。而中间真正做事的一段内容,是需要重点关注的。前面两个事件,分别是Write_rows和Update_rows,它们的时间是10:10:44,而后面三个Write_rows事件的时间是10:11:35,中间长达51秒钟,这段时间做什么了?
再核对一下事务83631679中的Update_rows要修改的表的记录,与事务83631678中在10:10:44时间点发生的事件Update_rows所要修改的记录,是同一个表中的同一条记录。那肯定是要等待了。
数据库问题,都已经解释清楚了,现在唯一的问题,就是需要找到业务开发人员,问一句,那个事务在哪个表上,在那51秒钟的时间里做什么了?
DBA还要继续处理其他问题,接力棒现在就交给开发同学了,明天听你回话。
show processlist中的Time
下面的问题,可能是在实际运维过程中遇到的容易造成疑惑的问题,先来看看我们所熟知的show processlist结果,这里请重点关注结果中的Time列信息,如下。
mysql> show processlist\G *************************** 1. row *************************** Id: 1 User: zhufeng.wang Host: localhost:51703 db: NULL Command: Sleep Time: 5142 State: Info: NULL Rows_sent: 0 Rows_examined: 0 *************************** 2. row *************************** Id: 2 User: zhufeng.wang Host: localhost:62898 db: local Command: Sleep Time: 2077 State: Info: NULL Rows_sent: 2 Rows_examined: 2
上面两行信息中,Time值分别是5142和2077,它们是怎么来的呢?对于这个问题,各位同学应该都是比较清楚的,它代表的是当前语句在执行时的时间点,与执行show processlist命令时的时间差,从下面的MySQL代码中可以证明这一点。
/* 用来计算Show Processlist中的Time列的值,thd_info->start_time 代表线程thd_info执行最后一个语句时的开始时间 */ if (thd_info->start_time) protocol->store_long ((longlong) (now - thd_info->start_time)); else protocol->store_null();
现在可以做一个实验,开两个会话,连接同一个MySQL服务器,一个会话(会话1)用来做实验,另一个会话(会话2)用来不断地执行show processlist命令以观察现象,实验结果很明确,只要会话1保持无操作,在会话2的结果中,会话1的连接对应的Time值一直在增长,而只要会话1执行任意一个命令,会话2的结果中,会话1的连接对应的Time值会被清零一次,然后再次继续增长,如此往复循环。在了解上述内容之后,这个现象现在应该很容易理解了,因为在执行任意命令时(调用函数dispatch_command),都会执行thd->set_time(),将时间清为当前时间,即时间差被清零。
但是有没有见过如下这样的现象?
mysql> show processlist\G *************************** 1. row *************************** Id: 2 User: zhufeng.wang Host: localhost:62898 db: local Command: Query Time: 1203070 State: User sleep Info: select sleep(100) Rows_sent: 0 Rows_examined: 0 ...其他省略...
可以看到,此时会话1的Time值高达1203070,而对应的语句只是select sleep(100)。是不是感到很奇怪,为什么只睡了100秒,而Time可以那么高?
当然,这里的语句是自己构造的,同时还发现,不管这样的语句执行多少次,Time依然保持上涨,并不会清零,这是什么原因?
很明显,这样的现象会给DBA造成一些困惑,在解决问题时会造成干扰,所以有必要在这里解释清楚。下面重点看一下set_time这个函数的实现。
inline void set_time() { /* 获取当前timestamp,存到start_utime变量中 */ start_utime= utime_after_lock= my_micro_time(); if (user_time.tv_sec || user_time.tv_usec) { /* 这里发现,当user_time不为0时,上面获取到的timestamp直接 被忽略了,而是使用了user_time的值,也就是说,只要user_time 的值不变,那么set_time的操作就不会改变当前连接的最新时间值, 我们就需要研究清楚,user_time到底是什么!*/ start_time= user_time; } else /* 正常路径下,如果user_time为0,则更新当前连接最新时间*/ my_micro_time_to_timeval(start_utime, &start_time); }
上面代码中提到的参数user_time,实际上对应的是MySQL会话参数timestamp,只要显式地设置了这个参数,user_time就不为0,那么当前会话的起始时间就被固定在这一刻了。
现在明白了,只要在会话1中执行一条命令,比如set timestamp=1490264145;,然后在会话2中观察,就会发现,Time不仅非常大,而且在会话1中再执行任何语句时,会话2中的Time值都不会被清零了。
所以,如果在实际运维中遇到这样的问题,就可以找一下有没有连接执行过这样的语句,从而造成了这样的假象,因为这样的问题出现时,都会把这类语句误判为慢查询,而实际又找不到这样的查询。
这个问题是不是有种似曾相识的感觉?没错,在Binlog里经常会遇到这样的命令,这是MySQL为了保持主从执行环境的一致性而做的,但如果在主库上这样操作,经常是不仅不好玩,反而会造成一头雾水的感觉。
总结
这个问题,看似简单,实则涉及很多关于Binlog的细节问题。讲这些的主要目的就是让DBA同学了解时间戳在Binlog中的作用及产生方法,以便在出现一些这方面怪异的问题时,做到心中有数,胸有成竹。
引自
http://www.broadview.com.cn/article/310