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，舒服~