返回 登录
0

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

阅读4207

引言:本文从一个典型的案例入手来讲述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核心原理与最佳实践》,点此链接可在博文视点官网查看此书。
                      图片描述

评论