MySQL數(shù)據(jù)庫(kù)binlog記錄的時(shí)間戳失序的原因
MySQL數(shù)據(jù)庫(kù)操作中，在做mysql binlog解析的時(shí)候，發(fā)現(xiàn)dump出來(lái)的數(shù)據(jù)出現(xiàn)嚴(yán)重的失序情況，時(shí)差差不多為1s，如下所示：
- SET TIMESTAMPE = 1
- SET TIMESTAMPE = 0
- SET TIMESTAMPE = 1
- ……
在寫binlog頭時(shí)：
- 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);
- }
///發(fā)現(xiàn)if when總是為正。
于是跟進(jìn)到上層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);
這里會(huì)構(gòu)建一個(gè)binlog的結(jié)構(gòu)體，構(gòu)建之后，其qinfo->when已經(jīng)被賦值。
繼續(xù)跟進(jìn)，在query_log_event的構(gòu)造函數(shù)里，會(huì)先調(diào)用log_event的構(gòu)造函數(shù)。
- 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;
- }
下面看看在哪個(gè)函數(shù)里會(huì)設(shè)置thd的start_time值，我們跟到dispatch_command函數(shù)里，打印thd->start_time：
- (gdb) p thd->start_time
- $52 = 1312428114
發(fā)現(xiàn)這個(gè)值與上一條命令中thd的start_time是一致的，表明該線程被重復(fù)使用，該字段尚未初始化。
繼續(xù)執(zhí)行:n
在執(zhí)行到thd->set_time()之后，發(fā)現(xiàn)start_time的值發(fā)生了變化：
- (gdb) p thd->start_time
- $55 = 1312428349
之后將斷點(diǎn)設(shè)置在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*/;
總上分析，我們可以認(rèn)為，在binlog中記錄的時(shí)間戳，其實(shí)在接受到命令之后，尚未執(zhí)行之前，就已經(jīng)確定了，其值被記錄在thd的start_time字段中。這就很好理解binlog中的時(shí)間戳失序的問(wèn)題，在一個(gè)高并發(fā)的mysql中，可能先提交的sql后執(zhí)行，從而導(dǎo)致binlog中的記錄時(shí)間戳失序。
關(guān)于MySQL數(shù)據(jù)庫(kù)binlog中記錄的時(shí)間戳失序的問(wèn)題就介紹到這里，希望通過(guò)本次的介紹能夠?qū)δ兴斋@！
【編輯推薦】
