MySQL binlog解析

binlog的解析

在自动提交的情况下执行一条insert语句，在binlog中是这样记录的：

# at 1512
#200315  0:17:28 server id 1  end_log_pos 1591 CRC32 0x3a2abd99 	Anonymous_GTID	last_committed=5	sequence_number=6

# at 1591
#200315  0:17:28 server id 1  end_log_pos 1668 CRC32 0x3a3b967a 	Query	thread_id=14	exec_time=0	error_code=0
SET TIMESTAMP=1584202648/*!*/;
BEGIN

# at 1668
#200315  0:17:28 server id 1  end_log_pos 1727 CRC32 0x942500b6 	Table_map: `person`.`user` mapped to number 78

# at 1727
#200315  0:17:28 server id 1  end_log_pos 1774 CRC32 0xff5614c3 	Write_rows: table id 78 flags: STMT_END_F
### INSERT INTO `person`.`user`
### SET
###   @1='y1'
###   @2=1
###   @3=12

# at 1774
#200315  0:17:28 server id 1  end_log_pos 1805 CRC32 0xe7b53c6b 	Xid = 109
COMMIT/*!*/;

binlog中记录的时间戳

#200315 0:17:28 server id 1 end_log_pos 1805 CRC32 0xe7b53c6b Xid = 109

200315 0:17:28就是binlog事件格式中的when，它记录了语句在执行前的时间。

Log_event::Log_event(
    THD* thd_arg, uint16 flags_arg,
    enum_event_cache_type cache_type_arg,
    enum_event_logging_type logging_type_arg,
    Log_event_header *header, Log_event_footer *footer)
  : is_valid_param(false), temp_buf(0), exec_time(0),
    event_cache_type(cache_type_arg), event_logging_type(logging_type_arg),
    crc(0), common_header(header), common_footer(footer), thd(thd_arg)
{
    server_id= thd->server_id;
    common_header->unmasked_server_id= server_id;    
    /* 这里就是用来在创建一个事件时，给这个事件的时间赋值的过程。
       可以看到，这个时间的来源是thd->start_time的值
    */
    common_header->when= thd->start_time;
    common_header->log_pos= 0;
    common_header->flags= flags_arg;
}

bool dispatch_command(THD *thd, const COM_DATA *com_data, 
                     enum enum_server_command command)
{   
	...
    /* 初始化这个时间为当前时间 */
    thd->set_time();
	

一条sql语句可以产生多个事件，每个事件的when都是一样的。
比如，在自动提交的场景下，执行一条update语句就会产生GTID、Query、Table_map、Update_rows、Xid事件，这些事件的时间戳都是一致的。

但是，当语句出现慢查询时，会出现不一样的结果，现通过以下场景来模拟sql的慢查询。
更新一条数据后休眠5s再提交事务，查看binlog，输入以下命令：

mysqlbinlog --base64-output=DECODE-ROWS -v ../data/binlog.000002 > ~/y.log

得到结果：

#200315 15:10:02 server id 1  end_log_pos 2177 CRC32 0xa549dd97 	Anonymous_GTID	last_committed=7	sequence_number=8	rbr_only=yes	original_committed_timestamp=1584256202990022	immediate_commit_timestamp=1584256202990022	transaction_length=293

#200315 15:09:57 server id 1  end_log_pos 2254 CRC32 0xe643dca9 	Query	thread_id=17	exec_time=5	error_code=0

#200315 15:09:57 server id 1  end_log_pos 2360 CRC32 0xa8c06827 	Update_rows: table id 78 flags: STMT_END_F

#200315 15:10:02 server id 1  end_log_pos 2391 CRC32 0xf213fcd5 	Xid = 178

由上可知，事务开始和结束的时间比执行插入的时间晚了5s。因为GTID和Xid事件是在commit语句执行的时候生成，mysql在写入binlog的时候，会将GTID事务放到前面。

在binlog中，还经常能看到set Timestamp语句，它的作用是保持主从执行环境的一致性。