对于解析MySQL的binlog用来更新其他数据存储的应用来说，binlog的顺序标识是很重要的。比如根据时间戳得到binlog位点作为解析起点。
但是binlog里面的事件，是否有稳定的有序性？
binlog中有三个看上去可能有序的信息：xid、timestamp、gno。本文分析这三个信息在binlog中的有序性。
Xid事件：根据事务提交顺序写入，而不是事务开始
当binlog格式为row，且事务中更新的是事务引擎时，每个事务的结束位置都有Xid，Xid的类型为整型。
MySQL中每个语句都会被分配一个全局递增的query_id(重启会被重置)，每个事务的Xid来源于事务第一个语句的query_id。
考虑一个简单的操作顺序：
session 1: begin; select; update;
session 2: begin; select; update; insert; commit;
session 1: insert; commit;
显然Xid2 > Xid1，但因为事务2会先于事务1记录写binlog，因此在这个binlog中，会出现Xid不是有序的情况。
TIMESTAMP也是事务提交顺序而写入的
时间戳的有序性可能是被误用最多的。在mysqlbinlog这个工具的输出结果中，每个事务起始有会输出一个SET TIMESTAMP=n。这个值取自第一个更新事件的时间。上一节的例子中,timestamp2>timestamp1,但因为事务2会先于事务1记录写binlog，因此在这个binlog中，会出现TIMESTAMP不是有序的情况。
GNO事务起始gtid事件
对于打开了gtid_mode的实例，每个事务起始位置都会有一个gtid event，其内容输出格式为UUID:gn，gno是一个整型数。
由于NEXT_GTID是可以直接指定的，因此若故意构造，可以很容易得到不是递增的情况，这里只讨论automatic模式下的有序性。
与上述两种情况不同，gno生成于事务提交时写binlog的时候。注意这里不是生成binlog，而是将binlog写入磁盘的时候。因此实现上确保了同一个UUID下gno的有序性。
小结
一个binlog文件中的Xid和TIMESTAMP无法保证有序性。在无特殊操作的情况下，相同的UUID可以保证gno的有序性。
show binlog events in 'mysql-bin.000011' limit 3330000,10000;
################################################
背景
MySQL 非 GTID 协议主备同步原理： 主库在执行 SQL 语句时产生binlog，在事务 commit 时将产生的binlog event写入binlog文件，备库IO线程通过 com_binlog_dump 用文件位置协议从主库拉取 binlog，将拉取的binlog存储到relaylog, SQL线程读取 relaylog 然后进行 apply，实现主备同步，在这个过程中有以下几个问题：
- 主库什么时间将产生的 binlog 真正刷到文件中？
- 备库IO线程从哪个位置读取主库的 binlog event 的？
- 备库SQL线程如何记录执行到的 relaylog 的位点？
- 备库IO线程何时将cache中的event 刷到relay log 文件中的?
问题分析
下面对这几个问题挨个解答。
问题 1: 主库什么时间将产生的binlog 真正刷到文件中
事务ordered_commit 中，会将 thd->cache_mngr 中的 binlog cache 写入到 binlog 文件中，但并没有执行fsync()操作，即只将文件内容写入到 OS 缓存中，详细 bt 为：
#0 my_write
#1 0x0000000000a92f50 in inline_mysql_file_write
#2 0x0000000000a9612e in my_b_flush_io_cache
#3 0x0000000000a43466 in MYSQL_BIN_LOG::flush_cache_to_file
#4 0x0000000000a43a4d in MYSQL_BIN_LOG::ordered_commit
#5 0x0000000000a429f2 in MYSQL_BIN_LOG::commit
#6 0x000000000063d3e2 in ha_commit_trans
#7 0x00000000008adb7a in trans_commit_stmt
#8 0x00000000007e511f in mysql_execute_command
#9 0x00000000007e7e0e in mysql_parse
#10 0x00000000007dae0e in dispatch_command
#11 0x00000000007d9634 in do_command
#12 0x00000000007a046d in do_handle_one_connection
#13 0x000000000079ff75 in handle_one_connection
#14 0x0000003a00a07851 in start_thread ()
#15 0x0000003a006e767d in clone ()
commit 时，会判断是否将产生的 binlog flush 到文件中，即执行 fsync操作，详细bt 为：
#0 MYSQL_BIN_LOG::sync_binlog_file
#1 0x0000000000a43c62 in MYSQL_BIN_LOG::ordered_commit
#2 0x0000000000a429f2 in MYSQL_BIN_LOG::commit
#3 0x000000000063d3e2 in ha_commit_trans
#4 0x00000000008adb7a in trans_commit_stmt
#5 0x00000000007e511f in mysql_execute_command
#6 0x00000000007e7e0e in mysql_parse
#7 0x00000000007dae0e in dispatch_command
#8 0x00000000007d9634 in do_command (thd=0x37a40160)
#9 0x00000000007a046d in do_handle_one_connection
#10 0x000000000079ff75 in handle_one_connection
#11 0x0000003a00a07851 in start_thread ()
#12 0x0000003a006e767d in clone ()
由 MYSQL_BIN_LOG::sync_binlog_file 可以看出，每提交一个事务，会 fsync 一次binlog file。 当 sync_binlog != 1 的时候，每次事务提交的时候，不一定会执行 fsync 操作，binlog 的内容只是缓存在了 OS（是否会执行fsync操作，取决于OS缓存的大小），此时备库可以读到主库产生的 binlog, 在这种情况下，当主库机器挂掉时，有以下两种情况：
- 主备同步无延迟，此时主库机器恢复后，备库接着之前的位点重新拉binlog, 但是主库由于没有fsync最后的binlog，所以会返回1236 的错误：
MySQL error code 1236 (ER_MASTER_FATAL_ERROR_READING_BINLOG): Got fatal error %d from master when reading data from binary log: '%-.256s' - 备库没有读到主库失去的binlog，此时备库无法同步主库最后的更新，备库不可用。
问题 2: 备库IO线程从哪个位置读取主库的binlog event 的
更新位点信息的 bt 如下：
#0 Rpl_info_table::do_flush_info (this=0x379cbf90, force=false)
#1 0x0000000000a78270 in Rpl_info_handler::flush_info
#2 0x0000000000a773b9 in Master_info::flush_info
#3 0x0000000000a5da4b in flush_master_info
#4 0x0000000000a697eb in handle_slave_io
#5 0x0000003a00a07851 in start_thread () from /lib64/libpthread.so.0
#6 0x0000003a006e767d in clone () from /lib64/libc.so.6
备库通过 master_log_info 来记录主库的相关信息，通过参数 sync_master_info 来设置备库经过多少个 binlog event 来更新已经读取到的位点信息。当stop slave时，会把正常的位点更新到master_log_info中，此时，如果最后的位点不是commit，则在start slave后，会继续上一位点拉取 binlog，从而造成同一个事务的binlog event分布在不同的binlog file中，此时如果执行顺利则不会有问题；如果在拉这个事务的过程中，sql 线程出错中断，在并行复制下会引起分发线程停在事务中间，再次启动的时候，会从上一次分发的事务继续分发，会造成在并行复制中不可分发的情况，因此需要注意。
当 sync_master_info > 1000时，可能在第1000个binlog 拉取的时候机器出问题，此时重启后会从主库多拉999个 binlog event，造成事务在备库多次执行问题，对于没有 primary key, unique key 可能会有问题，造成主备数据不一致，最常遇到的是1062问题。
问题3: 备库SQL线程如何记录执行到的relaylog 的位点
同问题2一样，相关的 bt 也类似，relay_log_info 记录的是备库已经执行了的最后的位点，这个位点不会处于事务中间，即是每 sync_relay_log_info 个事务更新一下这个位点。
相关bugs bug 原因: 备库异常 crash 后，可能造成事务在拉取过程中被重新拉取，binlog序列如下：
begin;
table_map;
begin;
table_map;
rows_log_event;
commit;
在并行复制条件下，由于出现了不完整的事务，所以会造成绑定事务信息无法恢复，造成hang的情况，详情见 bug 分析。
问题 4: 备库IO线程何时将cache中的event 刷到relay log 文件中的
这个问题的解答和问题1类似，也是以binlog event为单位的，当然也存在着和问题1中同样的问题，在此不在赘述。
结语
MySQL 通过 sync_binlog，sync_master_info，sync_relay_log_info，sync_relay_log 来记录相关的位点信息，出于性能考虑以及程序本身的健壮性，引入了各式要样的bug，类似的bug在此不在列举，那么有没有更好的方法来记录这些信息呢，当然有，即GTID 协议，会在下期月报分析。
################################################
# at 179666727 #191123 20:19:52 server id 3232266753 end_log_pos 179666788 GTID last_committed=557619 sequence_number=557620 rbr_only=no SET @@SESSION.GTID_NEXT= 'ceabbacf-0c77-11ea-b49f-2016d8c96b46:1662575'/*!*/; # at 179666788 #191123 20:19:52 server id 3232266753 end_log_pos 179666957 Query thread_id=557624 exec_time=0 error_code=0 use `google`/*!*/; SET TIMESTAMP=1574511592/*!*/; create table tb_person(id bigint(20) not null auto_increment,name varchar(255),primary key(id)) /*!*/; # at 179666957 #191123 20:23:50 server id 3232266753 end_log_pos 179667018 GTID last_committed=557620 sequence_number=557621 rbr_only=no SET @@SESSION.GTID_NEXT= 'ceabbacf-0c77-11ea-b49f-2016d8c96b46:1662576'/*!*/; # at 179667018 #191123 20:23:50 server id 3232266753 end_log_pos 179667185 Query thread_id=557624 exec_time=0 error_code=0 SET TIMESTAMP=1574511830/*!*/; create table tb_host(id bigint(20) not null auto_increment,name varchar(255),primary key(id)) /*!*/; # at 179667185 #191123 20:43:26 server id 3232266753 end_log_pos 179667246 GTID last_committed=557621 sequence_number=557622 rbr_only=yes /*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/; SET @@SESSION.GTID_NEXT= 'ceabbacf-0c77-11ea-b49f-2016d8c96b46:1662577'/*!*/; # at 179667246 #191123 20:43:26 server id 3232266753 end_log_pos 179667316 Query thread_id=557624 exec_time=0 error_code=0 SET TIMESTAMP=1574513006/*!*/; BEGIN /*!*/; # at 179667316 #191123 20:43:26 server id 3232266753 end_log_pos 179667373 Rows_query # insert into tb_host(name) values('5') # at 179667373 #191123 20:43:26 server id 3232266753 end_log_pos 179667424 Table_map: `google`.`tb_host` mapped to number 109 # at 179667424 #191123 20:43:26 server id 3232266753 end_log_pos 179667467 Write_rows: table id 109 flags: STMT_END_F ### INSERT INTO `google`.`tb_host` ### SET ### @1=1 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2='5' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */ # at 179667467 #191123 20:43:26 server id 3232266753 end_log_pos 179667494 Xid = 2788131 COMMIT/*!*/; # at 179667494 #191123 20:52:02 server id 3232266753 end_log_pos 179667555 GTID last_committed=557622 sequence_number=557623 rbr_only=yes /*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/; SET @@SESSION.GTID_NEXT= 'ceabbacf-0c77-11ea-b49f-2016d8c96b46:1662578'/*!*/; # at 179667555 #191123 20:52:02 server id 3232266753 end_log_pos 179667625 Query thread_id=557624 exec_time=0 error_code=0 SET TIMESTAMP=1574513522/*!*/; BEGIN /*!*/; # at 179667625 #191123 20:52:02 server id 3232266753 end_log_pos 179667684 Rows_query # update tb_host set name='10' where id=1 # at 179667684 #191123 20:52:02 server id 3232266753 end_log_pos 179667735 Table_map: `google`.`tb_host` mapped to number 109 # at 179667735 #191123 20:52:02 server id 3232266753 end_log_pos 179667792 Update_rows: table id 109 flags: STMT_END_F ### UPDATE `google`.`tb_host` ### WHERE ### @1=1 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2='5' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */ ### SET ### @1=1 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2='10' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */ # at 179667792 #191123 20:52:02 server id 3232266753 end_log_pos 179667819 Xid = 2788133 COMMIT/*!*/; # at 179667819 #191123 21:01:24 server id 3232266753 end_log_pos 179667880 GTID last_committed=557623 sequence_number=557624 rbr_only=yes /*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/; SET @@SESSION.GTID_NEXT= 'ceabbacf-0c77-11ea-b49f-2016d8c96b46:1662579'/*!*/; # at 179667880 #191123 21:01:24 server id 3232266753 end_log_pos 179667950 Query thread_id=557624 exec_time=0 error_code=0 SET TIMESTAMP=1574514084/*!*/; BEGIN /*!*/; # at 179667950 #191123 21:01:24 server id 3232266753 end_log_pos 179668000 Rows_query # delete from tb_host where id=1 # at 179668000 #191123 21:01:24 server id 3232266753 end_log_pos 179668051 Table_map: `google`.`tb_host` mapped to number 109 # at 179668051 #191123 21:01:24 server id 3232266753 end_log_pos 179668095 Delete_rows: table id 109 flags: STMT_END_F ### DELETE FROM `google`.`tb_host` ### WHERE ### @1=1 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2='10' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */ # at 179668095 #191123 21:01:24 server id 3232266753 end_log_pos 179668122 Xid = 2788134 COMMIT/*!*/; # at 179668122 #191123 21:11:42 server id 3232266753 end_log_pos 179668183 GTID last_committed=557624 sequence_number=557625 rbr_only=no SET @@SESSION.GTID_NEXT= 'ceabbacf-0c77-11ea-b49f-2016d8c96b46:1662580'/*!*/; # at 179668183 #191123 21:11:42 server id 3232266753 end_log_pos 179668303 Query thread_id=557624 exec_time=0 error_code=0 SET TIMESTAMP=1574514702/*!*/; SET @@session.pseudo_thread_id=557624/*!*/; DROP TABLE `tb_host` /* generated by server */ /*!*/; # at 179668303 #191123 21:19:09 server id 3232266753 end_log_pos 179668364 GTID last_committed=557625 sequence_number=557626 rbr_only=no SET @@SESSION.GTID_NEXT= 'ceabbacf-0c77-11ea-b49f-2016d8c96b46:1662581'/*!*/; # at 179668364 #191123 21:19:09 server id 3232266753 end_log_pos 179668493 Query thread_id=557624 exec_time=0 error_code=0 SET TIMESTAMP=1574515149/*!*/; alter table tb_person add column age smallint default 0 /*!*/; SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/; DELIMITER ; # End of log file /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/; /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/; #################################################### #################################################### #################################################### MySQL的二进制日志binlog可以说是MySQL最重要的日志，它记录了所有的DDL和DML语句（除了数据查询语句select），以事件形式记录，还包含语句所执行的消耗的时间，MySQL的二进制日志是事务安全型的。 MySQL binlog记录的所有操作实际上都有对应的事件类型的，譬如STATEMENT格式中的DML操作对应的是QUERY_EVENT类型，ROW格式下的DML操作对应的是ROWS_EVENT类型。 一、对于ROW格式的binlog，所有的DML语句都是记录在ROWS_EVENT中。 ROWS_EVENT分为三种：WRITE_ROWS_EVENT，UPDATE_ROWS_EVENT，DELETE_ROWS_EVENT，分别对应insert，update和delete操作。 1、对于insert操作，WRITE_ROWS_EVENT包含了要插入的数据 2、对于update操作，UPDATE_ROWS_EVENT不仅包含了修改后的数据，还包含了修改前的值。 3、对于delete操作，仅仅需要指定删除的主键（在没有主键的情况下，会给定所有列） 二、对于QUERY_EVENT事件，是以文本形式记录DML操作的。而对于ROWS_EVENT事件，并不是文本形式，所以在通过mysqlbinlog查看基于ROW格式的binlog时，需要指定-vv --base64-output=decode-rows。 mysqlbinlog常见的选项有以下几个： --start-datetime：从二进制日志中读取指定等于时间戳或者晚于本地计算机的时间 --stop-datetime：从二进制日志中读取指定小于时间戳或者等于本地计算机的时间 取值和上述一样 --start-position：从二进制日志中读取指定position 事件位置作为开始。 --stop-position：从二进制日志中读取指定position 事件位置作为事件截至 ######################################################################################################################################## ##################日志文件开头： Previous-GTIDs：ceabbacf-0c77-11ea-b49f-2016d8c96b46:1-1662585 # 表示前一个binlog中gtid值已经执行这个位置了。 # binlog版本，mysql服务器版本，binlog文件创建时间 /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/; /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/; DELIMITER /*!*/; # at 4 #191123 23:21:49 server id 3232266753 end_log_pos 123 Start: binlog v 4, server v 5.7.27-log created 191123 23:21:49 # Warning: this binlog is either in use or was not closed properly. # at 123 #191123 23:21:49 server id 3232266753 end_log_pos 190 Previous-GTIDs # ceabbacf-0c77-11ea-b49f-2016d8c96b46:1-1662585 ######################################################################################################################################## ################下面是共同的结尾，是二进制日志结尾的标志 SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/; DELIMITER ; # End of log file /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/; /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/; ###################################### ########stop事件： mysql服务停止时，会在当前的binlog日志添加一个stop事件,下次重启服务后会新开一个binlog日志，故当前的binlog日志必须给以标记： at stop # 表示stop事件 # at 356010155 #191123 4:03:12 server id 3232266753 end_log_pos 356010174 Stop SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/; DELIMITER ; # End of log file /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/; /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/; ######################################### ##############Rotate事件： 当binlog文件的大小达到max_binlog_size的值或者执行flush logs命令时，binlog会发生切换，这个时候会在当前的binlog日志添加一个ROTATE_EVENT事件，用于指定下一个日志的名称和位置： at Rotate to mysql-bin.000012 pos: 4 #表示下一个binlog日志的文件名称和位置 # at 179670297 #191123 23:21:49 server id 3232266753 end_log_pos 179670340 Rotate to mysql-bin.000012 pos: 4 SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/; DELIMITER ; # End of log file /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/; /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/; ######################################################################################################################################## 建表语句格式：以at开头，以“/*!*/;”结尾 # at 179666957 #191123 20:23:50 server id 3232266753 end_log_pos 179667018 GTID last_committed=557620 sequence_number=557621 rbr_only=no SET @@SESSION.GTID_NEXT= 'ceabbacf-0c77-11ea-b49f-2016d8c96b46:1662576'/*!*/; # at 179667018 #191123 20:23:50 server id 3232266753 end_log_pos 179667185 Query thread_id=557624 exec_time=0 error_code=0 SET TIMESTAMP=1574511830/*!*/; create table tb_host(id bigint(20) not null auto_increment,name varchar(255),primary key(id)) /*!*/; ######################################################################################################################################## 删除表语句格式：占用一个gtid_next 开头：at 结尾：/*!*/ # at 179668122 #191123 21:11:42 server id 3232266753 end_log_pos 179668183 GTID last_committed=557624 sequence_number=557625 rbr_only=no SET @@SESSION.GTID_NEXT= 'ceabbacf-0c77-11ea-b49f-2016d8c96b46:1662580'/*!*/; # at 179668183 #191123 21:11:42 server id 3232266753 end_log_pos 179668303 Query thread_id=557624 exec_time=0 error_code=0 SET TIMESTAMP=1574514702/*!*/; SET @@session.pseudo_thread_id=557624/*!*/; DROP TABLE `tb_host` /* generated by server */ /*!*/; ######################################################################################################################################## 修改表结构语句格式：占用一个gtid_next 开头：at 结尾：/*!*/ # at 179668303 #191123 21:19:09 server id 3232266753 end_log_pos 179668364 GTID last_committed=557625 sequence_number=557626 rbr_only=no SET @@SESSION.GTID_NEXT= 'ceabbacf-0c77-11ea-b49f-2016d8c96b46:1662581'/*!*/; # at 179668364 #191123 21:19:09 server id 3232266753 end_log_pos 179668493 Query thread_id=557624 exec_time=0 error_code=0 SET TIMESTAMP=1574515149/*!*/; alter table tb_person add column age smallint default 0 /*!*/; ######################################################################################################################################## insert语句：Write_rows类型，占用一个gtid_next 事件头以at开头， 事件体开头： “SET TIMESTAMP=1574513006/*!*/; BEGIN /*!*/;” # 中间是事件的具体内容 事件体结尾：“COMMIT/*!*/;” # at 179667185 #191123 20:43:26 server id 3232266753 end_log_pos 179667246 GTID last_committed=557621 sequence_number=557622 rbr_only=yes /*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/; SET @@SESSION.GTID_NEXT= 'ceabbacf-0c77-11ea-b49f-2016d8c96b46:1662577'/*!*/; # at 179667246 #191123 20:43:26 server id 3232266753 end_log_pos 179667316 Query thread_id=557624 exec_time=0 error_code=0 SET TIMESTAMP=1574513006/*!*/; BEGIN /*!*/; # at 179667316 #191123 20:43:26 server id 3232266753 end_log_pos 179667373 Rows_query # insert into tb_host(name) values('5') # at 179667373 #191123 20:43:26 server id 3232266753 end_log_pos 179667424 Table_map: `google`.`tb_host` mapped to number 109 # at 179667424 #191123 20:43:26 server id 3232266753 end_log_pos 179667467 Write_rows: table id 109 flags: STMT_END_F ### INSERT INTO `google`.`tb_host` ### SET ### @1=1 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2='5' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */ # at 179667467 #191123 20:43:26 server id 3232266753 end_log_pos 179667494 Xid = 2788131 COMMIT/*!*/; ############################################################ 测试一次插入多行： 发现：Write_rows这个内容与插入的数据量成正比。多个insert set语句 # at 179668493 #191123 22:05:11 server id 3232266753 end_log_pos 179668554 GTID last_committed=557626 sequence_number=557627 rbr_only=yes /*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/; SET @@SESSION.GTID_NEXT= 'ceabbacf-0c77-11ea-b49f-2016d8c96b46:1662582'/*!*/; # at 179668554 #191123 22:05:11 server id 3232266753 end_log_pos 179668624 Query thread_id=557625 exec_time=0 error_code=0 SET TIMESTAMP=1574517911/*!*/; BEGIN /*!*/; # at 179668624 #191123 22:05:11 server id 3232266753 end_log_pos 179668708 Rows_query # insert into tb_person (name,age) values('1',1),('5',5),('10',10) # at 179668708 #191123 22:05:11 server id 3232266753 end_log_pos 179668762 Table_map: `google`.`tb_person` mapped to number 111 # at 179668762 #191123 22:05:11 server id 3232266753 end_log_pos 179668836 Write_rows: table id 111 flags: STMT_END_F ### INSERT INTO `google`.`tb_person` ### SET ### @1=1 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2='1' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */ ### @3=1 /* SHORTINT meta=0 nullable=1 is_null=0 */ ### INSERT INTO `google`.`tb_person` ### SET ### @1=2 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2='5' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */ ### @3=5 /* SHORTINT meta=0 nullable=1 is_null=0 */ ### INSERT INTO `google`.`tb_person` ### SET ### @1=3 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2='10' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */ ### @3=10 /* SHORTINT meta=0 nullable=1 is_null=0 */ # at 179668836 #191123 22:05:11 server id 3232266753 end_log_pos 179668863 Xid = 2788147 COMMIT/*!*/; ######################################################################################################################################## 更新事务： Update_rows类型，占用一个gtid_next 事件头以at开头， 事件体的开头： SET TIMESTAMP=1574513522/*!*/; BEGIN /*!*/; # 中间是事件的内容 事件体的结尾： COMMIT/*!*/; # at 179667494 #191123 20:52:02 server id 3232266753 end_log_pos 179667555 GTID last_committed=557622 sequence_number=557623 rbr_only=yes /*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/; SET @@SESSION.GTID_NEXT= 'ceabbacf-0c77-11ea-b49f-2016d8c96b46:1662578'/*!*/; # at 179667555 #191123 20:52:02 server id 3232266753 end_log_pos 179667625 Query thread_id=557624 exec_time=0 error_code=0 SET TIMESTAMP=1574513522/*!*/; BEGIN /*!*/; # at 179667625 #191123 20:52:02 server id 3232266753 end_log_pos 179667684 Rows_query # update tb_host set name='10' where id=1 # at 179667684 #191123 20:52:02 server id 3232266753 end_log_pos 179667735 Table_map: `google`.`tb_host` mapped to number 109 # at 179667735 #191123 20:52:02 server id 3232266753 end_log_pos 179667792 Update_rows: table id 109 flags: STMT_END_F ### UPDATE `google`.`tb_host` ### WHERE ### @1=1 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2='5' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */ ### SET ### @1=1 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2='10' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */ # at 179667792 #191123 20:52:02 server id 3232266753 end_log_pos 179667819 Xid = 2788133 COMMIT/*!*/; ############################################################ 一次更新多条记录：Update_rows这个内容与插入的数据量成正比。多个update where set语句 # at 179668863 #191123 22:17:06 server id 3232266753 end_log_pos 179668924 GTID last_committed=557627 sequence_number=557628 rbr_only=yes /*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/; SET @@SESSION.GTID_NEXT= 'ceabbacf-0c77-11ea-b49f-2016d8c96b46:1662583'/*!*/; # at 179668924 #191123 22:17:06 server id 3232266753 end_log_pos 179668994 Query thread_id=557625 exec_time=0 error_code=0 SET TIMESTAMP=1574518626/*!*/; BEGIN /*!*/; # at 179668994 #191123 22:17:06 server id 3232266753 end_log_pos 179669052 Rows_query # update tb_person set name='glc',age=18 # at 179669052 #191123 22:17:06 server id 3232266753 end_log_pos 179669106 Table_map: `google`.`tb_person` mapped to number 111 # at 179669106 #191123 22:17:06 server id 3232266753 end_log_pos 179669229 Update_rows: table id 111 flags: STMT_END_F ### UPDATE `google`.`tb_person` ### WHERE ### @1=1 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2='1' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */ ### @3=1 /* SHORTINT meta=0 nullable=1 is_null=0 */ ### SET ### @1=1 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2='glc' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */ ### @3=18 /* SHORTINT meta=0 nullable=1 is_null=0 */ ### UPDATE `google`.`tb_person` ### WHERE ### @1=2 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2='5' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */ ### @3=5 /* SHORTINT meta=0 nullable=1 is_null=0 */ ### SET ### @1=2 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2='glc' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */ ### @3=18 /* SHORTINT meta=0 nullable=1 is_null=0 */ ### UPDATE `google`.`tb_person` ### WHERE ### @1=3 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2='10' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */ ### @3=10 /* SHORTINT meta=0 nullable=1 is_null=0 */ ### SET ### @1=3 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2='glc' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */ ### @3=18 /* SHORTINT meta=0 nullable=1 is_null=0 */ # at 179669229 #191123 22:17:06 server id 3232266753 end_log_pos 179669256 Xid = 2788148 COMMIT/*!*/; ######################################################################################################################################## 删除事务：Delete_rows类型，占用一个gtid_next 事件头以at开头， 事件体开头： “SET TIMESTAMP=1574513006/*!*/; #该时间戳就是"2019-11-23 21:01:24"的含义。表达了事件发生时间。 BEGIN /*!*/;” # 中间是事件的具体内容:thread_id、Rows_query、Table_map、Delete_rows、Xid # 即线程id、sql语句、操作的表对象、sql类型、事务结束标志Xid 事件体结尾：“COMMIT/*!*/;” # at 179667819 #191123 21:01:24 server id 3232266753 end_log_pos 179667880 GTID last_committed=557623 sequence_number=557624 rbr_only=yes /*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/; SET @@SESSION.GTID_NEXT= 'ceabbacf-0c77-11ea-b49f-2016d8c96b46:1662579'/*!*/; # at 179667880 #191123 21:01:24 server id 3232266753 end_log_pos 179667950 Query thread_id=557624 exec_time=0 error_code=0 SET TIMESTAMP=1574514084/*!*/; BEGIN /*!*/; # at 179667950 #191123 21:01:24 server id 3232266753 end_log_pos 179668000 Rows_query # delete from tb_host where id=1 # at 179668000 #191123 21:01:24 server id 3232266753 end_log_pos 179668051 Table_map: `google`.`tb_host` mapped to number 109 # at 179668051 #191123 21:01:24 server id 3232266753 end_log_pos 179668095 Delete_rows: table id 109 flags: STMT_END_F ### DELETE FROM `google`.`tb_host` ### WHERE ### @1=1 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2='10' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */ # at 179668095 #191123 21:01:24 server id 3232266753 end_log_pos 179668122 Xid = 2788134 COMMIT/*!*/; ######################################################################################## 一次删除多条记录：Update_rows这个内容与插入的数据量成正比。多个delete from where语句 # at 179669256 #191123 22:22:54 server id 3232266753 end_log_pos 179669317 GTID last_committed=557628 sequence_number=557629 rbr_only=yes /*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/; SET @@SESSION.GTID_NEXT= 'ceabbacf-0c77-11ea-b49f-2016d8c96b46:1662584'/*!*/; # at 179669317 #191123 22:22:54 server id 3232266753 end_log_pos 179669387 Query thread_id=557625 exec_time=0 error_code=0 SET TIMESTAMP=1574518974/*!*/; BEGIN /*!*/; # at 179669387 #191123 22:22:54 server id 3232266753 end_log_pos 179669429 Rows_query # delete from tb_person # at 179669429 #191123 22:22:54 server id 3232266753 end_log_pos 179669483 Table_map: `google`.`tb_person` mapped to number 111 # at 179669483 #191123 22:22:54 server id 3232266753 end_log_pos 179669562 Delete_rows: table id 111 flags: STMT_END_F ### DELETE FROM `google`.`tb_person` ### WHERE ### @1=1 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2='glc' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */ ### @3=18 /* SHORTINT meta=0 nullable=1 is_null=0 */ ### DELETE FROM `google`.`tb_person` ### WHERE ### @1=2 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2='glc' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */ ### @3=18 /* SHORTINT meta=0 nullable=1 is_null=0 */ ### DELETE FROM `google`.`tb_person` ### WHERE ### @1=3 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2='glc' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */ ### @3=18 /* SHORTINT meta=0 nullable=1 is_null=0 */ # at 179669562 #191123 22:22:54 server id 3232266753 end_log_pos 179669589 Xid = 2788149 COMMIT/*!*/; ####################################################################### ################################### 删除数据库 at GTID at 251 # drop开始位置为251 end_log_pos 345 Query # drop结束位置是345 第一：GTID事件 第二：Query事件，在这里就是具体的drop事件 # at 190 #191124 0:17:14 server id 3232266753 end_log_pos 251 GTID last_committed=0 sequence_number=1 rbr_only=no SET @@SESSION.GTID_NEXT= 'ceabbacf-0c77-11ea-b49f-2016d8c96b46:1662586'/*!*/; # at 251 #191124 0:17:14 server id 3232266753 end_log_pos 345 Query thread_id=557625 exec_time=0 error_code=0 SET TIMESTAMP=1574525834/*!*/; SET @@session.pseudo_thread_id=557625/*!*/; SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/; SET @@session.sql_mode=1436549120/*!*/; SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/; /*!C utf8 *//*!*/; SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=45/*!*/; SET @@session.lc_time_names=0/*!*/; SET @@session.collation_database=DEFAULT/*!*/; drop database google /*!*/; ############################################# 先插入三条数据，再修改一条数据，再删除一条数据 at # GTID事件。设置事务隔离级别和GTID_NEXT GTID SET TRANSACTION ISOLATION LEVEL SET @@SESSION.GTID_NEXT at # Query事件。报告服务端的线程thread_id和事务开始标志BEGIN Query at # Rows_query事件。报告表面执行语句 Rows_query at # Table_map事件。报告操作的表 Table_map at # Write_rows/Update_rows/Delete_rows事件。报告实际执行语句的具体内容 Write_rows/Update_rows/Delete_rows at # Xid事件。 Xid # 报告事务结束，每个事务都有唯一的Xid和GTID,在事务提交时，不管是STATEMENT还是ROW格式的binlog，都会在末尾添加一个XID_EVENT事件代表事务的结束。该事件记录了该事务的ID，在MySQL进行崩溃恢复时，根据事务在binlog中的提交情况来决定是否提交存储引擎中状态为prepared的事务。 --xid行给的时间减去最开始的GTID行给的时间就是事务时间。 --xid行给的end_log_pos表示该事务结束的pos位置点。 Xid事件分析： # at 179670270 #191123 22:29:07 server id 3232266753 end_log_pos 179670297 Xid = 2788151 COMMIT/*!*/; 第一：Xid = 2788151 #表示这是一个事务结束标志，其事务id为2788151，第2788151个事务。 第二：191123 22:29:07 # 表示该事务的结束时间为2019-11-23 22:29:07 第三：at 179670270 # 表示Xid事件的开始位置是179670270 第四：end_log_pos 179670297 # 表示Xid事件的截止位置为179670297 第五：COMMIT/*!*/; # 表示这是一个dml事务类型的commit结束标志。若为/*!*/; 表示ddl语句 事务语句：Rows_query+Table_map+Write_rows/Update_rows/Delete_rows组成，其余部分相同 事务结束标志：Xid # at 179669589 #191123 22:29:07 server id 3232266753 end_log_pos 179669650 GTID last_committed=557626 sequence_number=557630 rbr_only=yes /*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/; SET @@SESSION.GTID_NEXT= 'ceabbacf-0c77-11ea-b49f-2016d8c96b46:1662585'/*!*/; # at 179669650 #191123 22:27:59 server id 3232266753 end_log_pos 179669720 Query thread_id=557625 exec_time=0 error_code=0 SET TIMESTAMP=1574519279/*!*/; BEGIN /*!*/; # at 179669720 #191123 22:27:59 server id 3232266753 end_log_pos 179669804 Rows_query # insert into tb_person (name,age) values('1',1),('5',5),('10',10) # at 179669804 #191123 22:27:59 server id 3232266753 end_log_pos 179669858 Table_map: `google`.`tb_person` mapped to number 111 # at 179669858 #191123 22:27:59 server id 3232266753 end_log_pos 179669932 Write_rows: table id 111 flags: STMT_END_F ### INSERT INTO `google`.`tb_person` ### SET ### @1=4 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2='1' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */ ### @3=1 /* SHORTINT meta=0 nullable=1 is_null=0 */ ### INSERT INTO `google`.`tb_person` ### SET ### @1=5 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2='5' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */ ### @3=5 /* SHORTINT meta=0 nullable=1 is_null=0 */ ### INSERT INTO `google`.`tb_person` ### SET ### @1=6 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2='10' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */ ### @3=10 /* SHORTINT meta=0 nullable=1 is_null=0 */ # at 179669932 #191123 22:28:32 server id 3232266753 end_log_pos 179670002 Rows_query # update tb_person set name='glc',age=18 where age=1 # at 179670002 #191123 22:28:32 server id 3232266753 end_log_pos 179670056 Table_map: `google`.`tb_person` mapped to number 111 # at 179670056 #191123 22:28:32 server id 3232266753 end_log_pos 179670118 Update_rows: table id 111 flags: STMT_END_F ### UPDATE `google`.`tb_person` ### WHERE ### @1=4 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2='1' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */ ### @3=1 /* SHORTINT meta=0 nullable=1 is_null=0 */ ### SET ### @1=4 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2='glc' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */ ### @3=18 /* SHORTINT meta=0 nullable=1 is_null=0 */ # at 179670118 #191123 22:29:01 server id 3232266753 end_log_pos 179670171 Rows_query # delete from tb_person where age=5 # at 179670171 #191123 22:29:01 server id 3232266753 end_log_pos 179670225 Table_map: `google`.`tb_person` mapped to number 111 # at 179670225 #191123 22:29:01 server id 3232266753 end_log_pos 179670270 Delete_rows: table id 111 flags: STMT_END_F ### DELETE FROM `google`.`tb_person` ### WHERE ### @1=5 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2='5' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */ ### @3=5 /* SHORTINT meta=0 nullable=1 is_null=0 */ # at 179670270 #191123 22:29:07 server id 3232266753 end_log_pos 179670297 Xid = 2788151 COMMIT/*!*/; ############################################################# #################### 查看binlog日志 show binlog events [IN 'log_name'] [FROM pos] [LIMIT [offset,] row_count]; show binlog events in 'mysql-bin.000011' limit 3330000,10000; ################################################################ 恢复数据 ################################################################ 从binlog日志恢复数据 恢复命令的语法格式： mysqlbinlog mysql-bin.0000xx | mysql -u用户名 -p密码 数据库名 -------------------------------------------------------- 常用参数选项解释： --start-position=875 起始pos点 --stop-position=954 结束pos点 --start-datetime="2016-9-25 22:01:08" 起始时间点 --stop-datetime="2019-9-25 22:09:46" 结束时间点 --database=zyyshop 指定只恢复zyyshop数据库(一台主机上往往有多个数据库，只限本地log日志) -------------------------------------------------------- 不常用选项： -u --user=name 连接到远程主机的用户名 -p --password[=name] 连接到远程主机的密码 -h --host=name 从远程主机上获取binlog日志 --read-from-remote-server 从某个MySQL服务器上读取binlog日志
dscsddccdcd