The reason why MySQL database binlog records time stamps are out of order

MySQL databaseDuring the operationBinlogDuring parsing, we found that the dump data had serious out-of-order situations. The time difference was almost 1 s, as shown below:

 
 

  
  
SET TIMESTAMPE = 1 
  
  
 
  
  
SET TIMESTAMPE = 0 
  
  
 
  
  
SET TIMESTAMPE = 1 
  
  
 
  
  
…… 
 
 

When writing the binlog header:

 
 

  
  
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);  
  
  
 
  
  
} 
 
 

/// It is found that if when is always positive.

So follow up to the upper-layer 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); 
 
 

Here we will construct a binlog struct. After the build, its qinfo-> when has been assigned a value.

Continue to follow up. In the query_log_event constructor, The log_event constructor is called first.

 
 

  
  
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;  
  
  
 
  
  
} 
 
 

Next let's take a look at which function will set the start_time value of thd. We will follow the steps in the dispatch_command function to print thd-> start_time:

 
 

  
  
(gdb) p thd->start_time  
  
  
 
  
  
$52 = 1312428114 
 
 

It is found that this value is consistent with the start_time of thd in the previous command, indicating that the thread is used repeatedly and this field has not been initialized.

Continue execution: n

After thd-> set_time () is executed, it is found that the value of start_time has changed:

 
 

  
  
(gdb) p thd->start_time  
  
  
 
  
  
$55 = 1312428349 
 
 

Set the breakpoint in Log_event: write_header and observe the value of 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 
 
 

The values are consistent. Use mysqlbinlog to view the values:

 
 

  
  
# 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*/; 
 
 

In summary, we can think that the timestamp recorded in the binlog is determined after the command is received and has not been executed, the value is recorded in the start_time field of thd. This makes it easy to understandTime stamp out of orderIn a high-concurrency mysql, the SQL statement may be submitted before execution, resulting in a time stamp out of order in the binlog.

This article introduces the unsorted timestamp recorded in the binlog of MySQL database. We hope this article will help you gain some benefits!