《MySQL运维内参》节选 | Binlog中的时间戳（下）
ACMUG征集原创技术文章。详情请添加 A_CMUG或者扫描文末二维码关注我们的微信公众号。有奖征稿，请发送稿件至：acmug@acmug.com。
3306现金有奖征稿说明：知识无价，劳动有偿，ACMUG特约撰稿人有奖回报计划（修订版）
上文接：《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的慢查询记录要多说一点，锁等待的时间在这里是不计算入内的。所以如果是第二种原因，那慢查询就必然是查不到的，并且exec_time=5对这个也很有说服力，因为执行时间的计算是从开始时间到结束时间的差值，和慢查询计算方法不同，所以这也说明了这5秒钟时间都是在等待了。
那问题来了，它在等谁呢？竟然能等5秒钟？想必有另一个事务，拿到了它想要的锁，并且拿到锁的时间肯定超过5秒钟，那就需要继续找了。此时我们已经知道了，大事务有两种：
单条自动提交的语句，本身执行时间长（exec_time比较大）。
事务开始时间和结束时间的跨度长。
找ROW模式的Binlog，咱有利器啊，在其它章节中已经贴过的一个脚本，在这里再贴一次：
# 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列来表示。在分析之后，有如下结果：
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还要继续处理其它问题，接力棒现在就交给开发同学了，明天听你回话。
总结
这个问题，看似简单，实则涉及到很多关于Binlog的细节问题。讲这些的主要目的就是让DBA同学了解时间戳在Binlog中的作用以及产生方法，以便在出现一些这方面怪异的问题时，做到心中有数，胸有成竹。
欢迎关注：MySQL运维内参（formysql）
本书预售中，详情如下：
注：ACMUG收录技术文章版权属于原作者本人所有。如有疑问，请联系作者。
看完转发，手留余香。关注我们，一起进步。
关注ACMUG公众号，参与社区活动，交流开源技术，分享学习心得，一起共同进步。