MySQL數據庫binlog記錄的時間戳失序的原因

MySQL數據庫操作中，在做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中的記錄時間戳失序。

關於MySQL數據庫binlog中記錄的時間戳失序的問題就介紹到這裡，希望通過本次的介紹能夠對您有所收獲！