mysql binlog中的时间戳失序

问题：今天，在做mysql binlog解析的时候，发现dump出来的数据出现严重的失序情况，时差差不多为1s
例如
SET TIMESTAMPE = 1
SET TIMESTAMPE = 0
SET TIMESTAMPE = 1
……
///////////////////////////
在写binlog头时：log_event.cc
Log_event::write_header
  now= (ulong) get_time();     //query start time
int4store(header, now);              // timestamp


log_event.h
  inline time_t get_time()
  {
    THD *tmp_thd;
    if (when)
      return when;
    if (thd)
      return thd->start_time;
    if ((tmp_thd= current_thd))
      return tmp_thd->start_time;
    return my_time(0);
  }
///发现if when总是为正
于是跟进到上层binlog_query


  case THD::STMT_QUERY_TYPE:
    /*
      The MYSQL_LOG::write() function will set the STMT_END_F flag and
      flush the pending rows event if necessary.
     */
    {
      Query_log_event qinfo(this, query_arg, query_len, is_trans, suppress_use,
                            errcode);
这里会构建一个binlog的结构体，构建之后，其qinfo->when已经被赋值


继续跟进，在query_log_event的构造函数里，会先调用log_event的构造函数
Log_event::Log_event(THD* thd_arg, uint16 flags_arg, bool using_trans)
  :log_pos(0), temp_buf(0), exec_time(0), flags(flags_arg), thd(thd_arg)
{
  server_id= thd->server_id;
  when= thd->start_time;
  cache_stmt= using_trans;
}


---------------------------------------------------
下面看看在哪个函数里会设置thd的start_time值
我们跟到dispatch_command函数里
打印thd->start_time:
(gdb) p thd->start_time
$52 = 1312428114


发现这个值与上一条命令中thd的start_time是一致的，表明该线程被重复使用，该字段尚未初始化。
继续执行:n
在执行到thd->set_time()之后，发现start_time的值发生了变化：
(gdb) p thd->start_time
$55 = 1312428349
之后将断点设置在Log_event::write_header，并观察when的值
Breakpoint 3, Log_event::write_header (this=0x4923d2f0, file=0xcaf1b0, event_data_length=8) at log_event.cc:890
890     bool Log_event::write_header(IO_CACHE* file, ulong event_data_length)
(gdb) p when
$58 = 1312428349


可见这些值是一致的，使用mysqlbinlog查看：
# at 2586
#110804 11:25:49 server id 1  end_log_pos 2700  Query   thread_id=1     exec_time=70    error_code=0
SET TIMESTAMP=1312428349/*!*/;
insert into test values(NULL,'asdd','ssssdsdsss')
/*!*/;
# at 2700
#110804 11:25:49 server id 1  end_log_pos 2727  Xid = 14
COMMIT/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;


——————————————————————————
总上分析，我们可以认为，在binlog中记录的时间戳，其实在接受到命令之后，尚未执行之前，就已经确定了，其值被记录在thd的start_time字段中。这就很好理解binlog中的时间戳失序的问题，在一个高并发的mysql中，可能先提交的sql后执行，从而导致binlog中的记录时间戳失序