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语句,它的作用是保持主从执行环境的一致性。