MySQL运维案例分析：Binlog中的时间戳

栏目: 数据库 · 发布时间: 8年前

内容简介：MySQL运维案例分析：Binlog中的时间戳

引言：本文从一个典型的案例入手来讲述Binlog中时间戳的原理和实践，通过本文你可以了解时间戳在Binlog中的作用及产生方法，以便在出现一些这方面怪异的问题时，做到心中有数，胸有成竹。

本文选自《MySQL运维内参》

背景

众所周知，在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核心原理与最佳实践》，点此链接可在博文视点官网查看此书。

以上所述就是小编给大家介绍的《MySQL运维案例分析：Binlog中的时间戳》，希望对大家有所帮助，如果大家有任何疑问请给我留言，小编会及时回复大家的。在此也非常感谢大家对码农网的支持！

查看所有标签

猜你喜欢:

本站部分资源来源于网络，本站转载出于传递更多信息之目的，版权归原作者或者来源机构所有，如转载稿涉及版权问题，请联系我们。

码农书籍

Responsive Web Design

Ethan Marcotte / Happy Cog / 2011-6 / USD 18.00

From mobile browsers to netbooks and tablets, users are visiting your sites from an increasing array of devices and browsers. Are your designs ready? Learn how to think beyond the desktop and craft be......一起来看看《Responsive Web Design》这本书的介绍吧!

码农工具