背景

　　众所周知，在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中的作用及产生方法，以便在出现一些这方面怪异的问题时，做到心中有数，胸有成竹。
　　本文选自《MySQL运维内参：MySQL、Galera、Inception核心原理与最佳实践》，点此链接可在博文视点官网查看此书。
　　　　　　　　　　　　　　　　　　　　　　
　　想及时获得更多精彩文章，可在微信中搜索“博文视点”或者扫描下方二维码并关注。