mysql binlog 时间 set_MySQL数据库binlog记录的时间戳失序的原因

MySQL数据库操作中，在做mysql binlog解析的时候，发现dump出来的数据出现严重的失序情况，时差差不多为1s，如下所示：

SETTIMESTAMPE=1

SETTIMESTAMPE=0

SETTIMESTAMPE=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  Querythread_id=1exec_time=70error_code=0

SETTIMESTAMP=1312428349/*!*/;

insert into test values(NULL,'asdd','ssssdsdsss')

/*!*/;

# at 2700

#110804 11:25:49 server id 1  end_log_pos 2727Xid=14

COMMIT/*!*/;

DELIMITER ;

# End of log file

ROLLBACK /* added by mysqlbinlog */;

/*!50003 SETCOMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

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

关于MySQL数据库binlog中记录的时间戳失序的问题就介绍到这里，希望通过本次的介绍能够对您有所收获！

【编辑推荐】

【责任编辑：赵鹏 TEL：(010)68476606】

点赞 0