MySQL运维案例分析：Binlog中的时间戳
摘要：本文从一个典型的案例入手来讲述Binlog中时间戳的原理和实践，通过本文你可以了解时间戳在Binlog中的作用及产生方法，以便在出现一些这方面怪异的问题时，做到心中有数，胸有成竹。本文选自《MySQL运维内参》
背景
众所周知，在Binlog文件中，经常会看到关于事件的时间属性，出现的方式都是如下这样的。
#16121310:11:35serverid11766end_log_pos263690453CRC320xbee3aaf5Xid=83631678
我们清楚地知道，16121310:11:35表示的就是时间值，但除此之外呢？还能知道它的什么信息呢？
案例分析
先从一个典型的案例入手来讲述其中的细节，比如曾经在GaleraCluster碰到的一个问题，可以先看一段Binlog内容，如下。
#16121310:11:35serverid11766end_log_pos263677208CRC320xbfc41688GTID[commit=yes]
#16121310:10:44serverid11766end_log_pos263677291CRC320x02537685Querythread_id=4901481exec_time=0error_code=0
#16121310:10:44serverid11766end_log_pos263677435CRC320x0e70aab6Write_rows:tableid17852flags:STMT_END_F
#16121310:10:44serverid11766end_log_pos263677609CRC320xb58d4c61Update_rows:tableid17853flags:STMT_END_F
#16121310:11:35serverid11766end_log_pos263690453CRC320xbee3aaf5Xid=83631678#16121310:11:30serverid11766end_log_pos263690501CRC320x6e798470GTID[commit=yes]
#16121310:11:30serverid11766end_log_pos263690592CRC320x2b6a6d34Querythread_id=4900813exec_time=5error_code=0#16121310:11:30serverid11766end_log_pos263691291CRC320xc0f9ed87Update_rows:tableid17891flags:STMT_END_F
#16121310:11:30serverid11766end_log_pos263691322CRC320xe40764c4Xid=83631679#16121310:11:35serverid11766end_log_pos263691370CRC320xbaa4ca30GTID[commit=yes]#16121310:11:35serverid11766end_log_pos263691453CRC320x030f321cQuerythread_id=4900813exec_time=0error_code=0
#16121310:11:35serverid11766end_log_pos263692240CRC320x7584d6a1Delete_rows:tableid73flags:STMT_END_F#16121310:11:35serverid11766end_log_pos263692271CRC320x03abb120Xid=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,uint16flags_arg,
enum_event_cache_typecache_type_arg,
enum_event_logging_typelogging_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语句，在入口处理函数中就调用了，可以简单看一下，如下。
booldispatch_command(THD*thd,constCOM_DATA*com_data,
enumenum_server_commandcommand)
{/*localvariables...*/
thd->set_command(command);/*
Commandswhichalwaystakealongtimeareloggedinto
theslowlogonlyifopt_log_slow_admin_statementsisset.
*/
thd->enable_slow_log=TRUE;
thd->lex->sql_command=SQLCOM_END;/*toavoidconfusingVIEWdetectors*/
/*就是在这里，初始化这个时间为当前时间*/
thd->set_time();/*othercode...*/}
想必有些同学已经清楚了，其实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)
{
/*localvaiables*/
/*exec_timecalculationhaschangedtousethesamemethodthatisused
tofillout"thd_arg->start_time"*/
structtimevalend_time;
ulonglongmicro_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;
/*othercode...*/
}
那么现在就可以去解释事务83631679为什么执行了5秒钟，但所有事件的时间都是10:11:30了。就是因为这个事务是自动提交的，只有一条语句并且执行了5秒钟，就是这么简单，仅此而已。
因为是自动提交的，这个事务只有一条语句，thd->set_time()也只会被设置一次，所以这个事务中的所有事件，都停留在了这个时间点上，所以就出现了上面的现象。
发散思维
可能有同学有疑惑了，即使一个事务只有一条语句，那也是有提交的，提交时间确实是在5秒之后做的，难道内部没有做这个问题的处理？可以做一个实验来看一下，还是一个事务一条语句，但此时不是自动提交，而是一个事务开始之后，等待了5秒钟，再去手动提交，然后再看Binlog内容，如下：
mysql>setautocommit=0;
QueryOK,0rowsaffected(0.00sec)
mysql>insertintomy1values(13143306,'zhufeng');selectsleep(5);commit;
QueryOK,1rowaffected,0warning(0.00sec)
+----------+
|sleep(5)|
+----------+
|0|
+----------+
1rowinset(5.00sec)
QueryOK,0rowsaffected(0.01sec)
为了没有时间误差，上面的三条语句是同时执行的，中间做了5秒的等待操作，现在看一下对应的Binlog内容。
#16121612:53:25serverid23932end_log_pos449CRC320x2939a45bGTID[commit=yes]
#16121612:53:20serverid23932end_log_pos522CRC320x1df41360Querythread_id=21exec_time=error_code=0
#16121612:53:20serverid23932end_log_pos614CRC320xf1515ed0Write_rows:tableid78flags:STMT_END_F
#16121612:53:25serverid23932end_log_pos645CRC320x69c2d142Xid=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来构造GTID（具体请参考第15章）。这也就可以解释，为什么GTID这个事件对应的时间和Xid是一样的了，就是因为它的时间是从Commit语句那里继承过来的。当然，Xid也是同样的道理了，因为它们是同一个语句产生的两个不同事件。
但关于顺序问题，是与GTID这个事件的作用有关的。在MySQLBinlog中，必须要提前知道GTID的具体信息，所以在MySQL提交并组装对应的Binlog时将其放到了最前面，从而导致了目前看到的关于时间问题的现象。
问题延伸
再回过头来看一下，最开始等待5秒的案例如下。
#16121310:11:30serverid11766end_log_pos263690501CRC320x6e798470GTID[commit=yes]
#16121310:11:30serverid11766end_log_pos263690592CRC320x2b6a6d34Querythread_id=4900813exec_time=5error_code=0
#16121310:11:30serverid11766end_log_pos263691291CRC320xc0f9ed87Update_rows:tableid17891flags:STMT_END_F
#16121310:11:30serverid11766end_log_pos263691322CRC320xe40764c4Xid=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章中。
#vimsummarize_binlogs.sh
#!/bin/bash
BINLOG_FILE="mysql-bin.000046"
START_TIME="2015-06-288:45:00"
STOP_TIME="2015-06-2810: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,/#.*serverid/)){if(bg==1){statm=substr($1,2,6)""$2;cmd=sprintf("date-d\"%s\"+%%s",statm);cmd|getlineintsta;close(cmd);bg=0;bf=1;}
elseif(bf==1){endtm=substr($1,2,6)""$2;cmd=sprintf("date-d\"%s\"+%%s",endtm);cmd|getlineinttal;close(cmd);}}\if(match($0,/#.*Table_map:.*mappedtonumber/)){printf"Timestamp:"$1""$2"Table:"$(NF-4);flag=1}\elseif(match($0,/#.*Xid=.*/)){xid=$(NF)}\
elseif(match($0,/(###INSERTINTO.*..*)/)){count=count+1;insert_count=insert_count+1;s_type="INSERT";s_count=s_count+1;}\
elseif(match($0,/(###UPDATE.*..*)/)){count=count+1;update_count=update_count+1;s_type="UPDATE";s_count=s_count+1;}\
elseif(match($0,/(###DELETEFROM.*..*)/)){count=count+1;delete_count=delete_count+1;s_type="DELETE";s_count=s_count+1;}\
elseif(match($0,/^(#at)/)&&flag==1&&s_count>0){print"QueryType:"s_type""s_count"row(s)affected";s_type="";s_count=0;}\
elseif(match($0,/^(COMMIT)/)){period=inttal-intsta;if(inttal==0){period=0};print"[Transactiontotal:"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:~$catsum|grepTransaction|awk'{if($19>0)print}'[Transactiontotal:8Insert(s):8Update(s):0Delete(s):0Xid:83631021period:1]
[Transactiontotal:15Insert(s):10Update(s):4Delete(s):1Xid:83631137period:1]
[Transactiontotal:10Insert(s):7Update(s):3Delete(s):0Xid:83631517period:1]
[Transactiontotal:3Insert(s):3Update(s):0Delete(s):0Xid:83631658period:1]
[Transactiontotal:16Insert(s):10Update(s):6Delete(s):0Xid:83631678period:51]
[Transactiontotal:12Insert(s):9Update(s):3Delete(s):0Xid:83631829period:1]
[Transactiontotal:5Insert(s):4Update(s):1Delete(s):0Xid:83632139period:1]
[Transactiontotal:3Insert(s):3Update(s):0Delete(s):0Xid:83632172period:1]
[Transactiontotal:3Insert(s):3Update(s):0Delete(s):0Xid:83632206period:1]
很快发现，Xid为83631678的事务，竟然长达51秒。然后打开对应的Binlog文件找到这个事务，内容如下。
#16121310:11:35serverid11766end_log_pos263677208CRC320xbfc41688GTID[commit=yes]
#16121310:10:44serverid11766end_log_pos263677291CRC320x02537685Querythread_id=4901481exec_time=0error_code=0
#16121310:10:44serverid11766end_log_pos263677435CRC320x0e70aab6Write_rows:tableid17852flags:STMT_END_F
#16121310:10:44serverid11766end_log_pos263677609CRC320xb58d4c61Update_rows:tableid17853flags:STMT_END_F
#16121310:11:35serverid11766end_log_pos263685326CRC320xc512e73cWrite_rows:tableid566flags:STMT_END_F
#16121310:11:35serverid11766end_log_pos263685556CRC320x805318e4Write_rows:tableid566flags:STMT_END_F
#16121310:11:35serverid11766end_log_pos263690422CRC320x4de989c8Write_rows:tableid73flags:STMT_END_F
#16121310:11:35serverid11766end_log_pos263690453CRC320xbee3aaf5Xid=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还要继续处理其他问题，接力棒现在就交给开发同学了，明天听你回话。
showprocesslist中的Time
下面的问题，可能是在实际运维过程中遇到的容易造成疑惑的问题，先来看看我们所熟知的showprocesslist结果，这里请重点关注结果中的Time列信息，如下。
mysql>showprocesslist\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，它们是怎么来的呢？对于这个问题，各位同学应该都是比较清楚的，它代表的是当前语句在执行时的时间点，与执行showprocesslist命令时的时间差，从下面的MySQL代码中可以证明这一点。
/*用来计算ShowProcesslist中的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）用来不断地执行showprocesslist命令以观察现象，实验结果很明确，只要会话1保持无操作，在会话2的结果中，会话1的连接对应的Time值一直在增长，而只要会话1执行任意一个命令，会话2的结果中，会话1的连接对应的Time值会被清零一次，然后再次继续增长，如此往复循环。在了解上述内容之后，这个现象现在应该很容易理解了，因为在执行任意命令时（调用函数dispatch_command），都会执行thd->set_time()，将时间清为当前时间，即时间差被清零。
但是有没有见过如下这样的现象？
mysql>showprocesslist\G
***************************1.row***************************
Id:2
User:zhufeng.wang
Host:localhost:62898
db:local
Command:Query
Time:1203070
State:Usersleep
Info:selectsleep(100)
Rows_sent:0
Rows_examined:0
...其他省略...
可以看到，此时会话1的Time值高达1203070，而对应的语句只是selectsleep(100)。是不是感到很奇怪，为什么只睡了100秒，而Time可以那么高？
当然，这里的语句是自己构造的，同时还发现，不管这样的语句执行多少次，Time依然保持上涨，并不会清零，这是什么原因？
很明显，这样的现象会给DBA造成一些困惑，在解决问题时会造成干扰，所以有必要在这里解释清楚。下面重点看一下set_time这个函数的实现。
inlinevoidset_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中执行一条命令，比如settimestamp=1490264145;，然后在会话2中观察，就会发现，Time不仅非常大，而且在会话1中再执行任何语句时，会话2中的Time值都不会被清零了。
所以，如果在实际运维中遇到这样的问题，就可以找一下有没有连接执行过这样的语句，从而造成了这样的假象，因为这样的问题出现时，都会把这类语句误判为慢查询，而实际又找不到这样的查询。
这个问题是不是有种似曾相识的感觉？没错，在Binlog里经常会遇到这样的命令，这是MySQL为了保持主从执行环境的一致性而做的，但如果在主库上这样操作，经常是不仅不好玩，反而会造成一头雾水的感觉。
总结
这个问题，看似简单，实则涉及很多关于Binlog的细节问题。讲这些的主要目的就是让DBA同学了解时间戳在Binlog中的作用及产生方法，以便在出现一些这方面怪异的问题时，做到心中有数，胸有成竹。
本文选自《MySQL运维内参：MySQL、Galera、Inception核心原理与最佳实践》，点此链接可在博文视点官网查看此书。
图片描述
想及时获得更多精彩文章，可在微信中搜索“博文视点”或者扫描下方二维码并关注。
图片描述
用云栖社区APP，舒服~