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

数据库 MySQL
MySQL数据库在binlog中记录的时间戳,在接受到命令之后,尚未执行之前,就已经确定,其值被记录在thd的start_time字段中。因此在一个高并发的MySQL中,可能先提交的SQL后执行,从而导致binlog中的记录时间戳失序。

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

 

  1. SET TIMESTAMPE = 1 
  2.  
  3. SET TIMESTAMPE = 0 
  4.  
  5. SET TIMESTAMPE = 1 
  6.  
  7. …… 

 

在写binlog头时:

  1. log_event.cc  
  2.  
  3. Log_event::write_header  
  4.  
  5. now= (ulong) get_time();     //query start time  
  6.  
  7. int4store(header, now);              // timestamp  
  8.  
  9. log_event.h  
  10.  
  11. inline time_t get_time()  
  12.  
  13. {  
  14.  
  15. THD *tmp_thd;  
  16.  
  17. if (when)  
  18.  
  19. return when;  
  20.  
  21. if (thd)  
  22.  
  23. return thd->start_time;  
  24.  
  25. if ((tmp_thdcurrent_thd))  
  26.  
  27. return tmp_thd->start_time;  
  28.  
  29. return my_time(0);  
  30.  

 

///发现if when总是为正。

于是跟进到上层binlog_query:

  1. case THD::STMT_QUERY_TYPE:  
  2.  
  3. /*  
  4.  
  5. The MYSQL_LOG::write() function will set the STMT_END_F flag and  
  6.  
  7. flush the pending rows event if necessary.  
  8.  
  9. */  
  10.  
  11. {  
  12.  
  13. Query_log_event qinfo(this, query_arg, query_len, is_trans, suppress_use,  
  14.  
  15.                       errcode); 

 

这里会构建一个binlog的结构体,构建之后,其qinfo->when已经被赋值。

继续跟进,在query_log_event的构造函数里,会先调用log_event的构造函数。

 

  1. Log_event::Log_event(THD* thd_arg, uint16 flags_arg, bool using_trans)  
  2.  
  3. :log_pos(0), temp_buf(0), exec_time(0), flags(flags_arg), thd(thd_arg)  
  4.  
  5. {  
  6.  
  7. server_idthd->server_id;  
  8.  
  9. whenthd->start_time;  
  10.  
  11. cache_stmtusing_trans;  
  12.  

 

下面看看在哪个函数里会设置thd的start_time值,我们跟到dispatch_command函数里,打印thd->start_time:

 

  1. (gdb) p thd->start_time  
  2.  
  3. $52 = 1312428114 

 

发现这个值与上一条命令中thd的start_time是一致的,表明该线程被重复使用,该字段尚未初始化。

继续执行:n

在执行到thd->set_time()之后,发现start_time的值发生了变化:

 

  1. (gdb) p thd->start_time  
  2.  
  3. $55 = 1312428349 

 

之后将断点设置在Log_event::write_header,并观察when的值

 

  1. Breakpoint 3, Log_event::write_header (this=0x4923d2f0file=0xcaf1b0event_data_length=8) at log_event.cc:890  
  2.  
  3. 890     bool Log_event::write_header(IO_CACHE* file, ulong event_data_length)  
  4.  
  5. (gdb) p when  
  6.  
  7. $58 = 1312428349 

 

可见这些值是一致的,使用mysqlbinlog查看:

 

  1. # at 2586  
  2.  
  3. #110804 11:25:49 server id 1  end_log_pos 2700  Query   thread_id=1     exec_time=70    error_code=0 
  4.  
  5. SET TIMESTAMP=1312428349/*!*/;  
  6.  
  7. insert into test values(NULL,'asdd','ssssdsdsss')  
  8.  
  9. /*!*/;  
  10.  
  11. # at 2700  
  12.  
  13. #110804 11:25:49 server id 1  end_log_pos 2727  Xid = 14 
  14.  
  15. COMMIT/*!*/;  
  16.  
  17. DELIMITER ;  
  18.  
  19. # End of log file  
  20.  
  21. ROLLBACK /* added by mysqlbinlog */;  
  22.  
  23. /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/; 

 

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

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

【编辑推荐】

  1. Oracle数据库如何创建虚拟列和复合触发器
  2. MySQL数据库目录结构及常用命令的使用总结篇
  3. 利用C#对XML文档和数据库操作的四个技术节点
  4. 以MySQL为例介绍数据库测试工具dbmonster的使用
  5. Oracle基于用户管理的备份与恢复之归档日志和参数文件
责任编辑:赵鹏 来源: CSDN博客
相关推荐

2011-07-11 14:36:10

BinlogMysql

2010-05-24 17:54:25

2011-08-09 13:34:56

MySQL数据库负荷较高

2011-08-29 16:27:16

MySQL时间类型

2011-08-01 16:31:29

MySQL数据库外键

2019-09-16 08:28:17

Mysql数据库binlog

2010-06-01 17:45:57

MySQL数据库

2018-09-11 17:13:23

MySQ数据库重复记录

2010-05-25 10:44:51

MySQL数据库

2010-05-21 10:22:37

MySQL数据库

2011-03-08 08:49:55

MySQL优化单机

2010-05-31 10:09:16

MySQL数据库

2011-05-13 09:42:21

2010-04-02 18:30:41

Oracle数据库

2011-02-22 14:26:04

ProFTPD

2011-02-22 14:26:04

ProFTPD

2011-05-24 14:48:46

压缩数据库

2023-09-01 15:34:34

数据库开发

2011-03-09 08:53:02

MySQL优化集群

2023-02-16 17:44:13

点赞
收藏

51CTO技术栈公众号