mysql的binlog定位分析问题

一． 问题

我们开发中有时候会遇到这样的问题，mysql某个表字段代码上应该被修改，但数据库里却还是原来的值，如果代码里没有很详细的日志记录，这时候我们很难确定是真的没有被修改，还是被修改了，又被其他操作修改成原来的值。

二． Binlog

Binlog是mysql用来记录数据变化的日志。通过binlog我们可以恢复数据，也可以跟踪数据的修改记录。Binlog有三种模式：

1. Statement Level模式: 每一条修改数据的sql记录到binlog中
   日志量少，但遇到sql中使用now()等sql函数，恢复数据时导致数据的不一致性
2. Row Level模式：修改后的每一条数据记录到binlog中
   日志量大，但不会有数据不一致问题
3. 混合模式：前面两种模式优点的混合，根据sql的特点决定Statement Level模式或者Row Level模式。

了解binlog后，针对上面问题我们可以通过binlog确定数据是否是修改后又被修改回原来的值。

三． 步骤分析

## 通过该命令将binlog转成可读的文本文件
mysqlbinlog -vv --base64-output=decode-rows mysql-bin.000019 > mysql-bin.000019.txt

## 通过grep查找我们关心的数据，表名是需要查询表的名称，5575是我的id字段，更新操作是根据id执行的
cat mysql-bin.002997.txt |grep -C 10 'UPDATE.*表名' | grep -C 10 '5575'

#211011 14:58:36 server id 1  end_log_pos 575657083 CRC32 0x18a3591a 	Query	thread_id=633567	exec_time=0	error_code=0
SET TIMESTAMP=1633935516/*!*/;
## BEGIN 到 COMMIT之前为一个事务
BEGIN
/*!*/;
# at 575657083
#211011 14:58:36 server id 1  end_log_pos 575657226 CRC32 0xcc528ff5 	Table_map: `databaseName`.`tableName` mapped to number 708
# at 575657226
#211011 14:58:36 server id 1  end_log_pos 575657286 CRC32 0x9024b4cd 	Update_rows: table id 708 flags: STMT_END_F
## 这里就是我们的sql语句，字段名并不会记录在日志中，通过‘@数字’表示，数字表示字段在表中的顺序
## update table set field1=3, field2='2021-10-11 14:58:36' where id=5575(第一次修改)
### UPDATE `databaseName`.`tableName`
### WHERE
###   @1=5575 /* LONGINT meta=0 nullable=0 is_null=0 */
### SET
###   @28=3 /* TINYINT meta=0 nullable=0 is_null=0 */
###   @33='2021-10-11 14:58:36' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
# at 575657286
#211011 14:58:36 server id 1  end_log_pos 575657317 CRC32 0xd6aeea5e 	Xid = 209535256
COMMIT/*!*/;
# at 575657317
#211011 14:58:38 server id 1  end_log_pos 575657382 CRC32 0x29352615 	Anonymous_GTID	last_committed=218743	sequence_number=218744	rbr_only=yes
--
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
--
#211011 15:03:05 server id 1  end_log_pos 575856468 CRC32 0x9b47ef01 	Query	thread_id=633742	exec_time=2	error_code=0
SET TIMESTAMP=1633935785/*!*/;
BEGIN
/*!*/;
# at 575856468
#211011 15:03:05 server id 1  end_log_pos 575856611 CRC32 0xfe87019a 	Table_map: `databaseName`.`tableName` mapped to number 708
# at 575856611
#211011 15:03:05 server id 1  end_log_pos 575856671 CRC32 0xa5b3c7f5 	Update_rows: table id 708 flags: STMT_END_F
## update table set field1=4, field2='2021-10-11 15:03:05' where id=5575(第二次修改)
### UPDATE `databaseName`.`tableName`
### WHERE
###   @1=5575 /* LONGINT meta=0 nullable=0 is_null=0 */
### SET
###   @28=4 /* TINYINT meta=0 nullable=0 is_null=0 */
###   @33='2021-10-11 15:03:05' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
# at 575856671
#211011 15:03:07 server id 1  end_log_pos 575856848 CRC32 0x87f358c3 	Table_map: `databaseName`.`tableName` mapped to number 7612
# at 575856848
#211011 15:03:07 server id 1  end_log_pos 575856917 CRC32 0x07cf24f0 	Update_rows: table id 7612 flags: STMT_END_F
### UPDATE `databaseName`.`tableName`
--
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
--
#211011 15:00:23 server id 1  end_log_pos 575857871 CRC32 0x2b00c398 	Query	thread_id=633677	exec_time=206	error_code=0
SET TIMESTAMP=1633935623/*!*/;
BEGIN
/*!*/;
# at 575857871
#211011 15:00:23 server id 1  end_log_pos 575858014 CRC32 0xe3970e29 	Table_map: `databaseName`.`tableName` mapped to number 708
# at 575858014
#211011 15:00:23 server id 1  end_log_pos 575858074 CRC32 0xfc0169a1 	Update_rows: table id 708 flags: STMT_END_F
## update table set field1=3, field2='2021-10-11 15:00:23' where id=5575(第三次修改)
### UPDATE `databaseName`.`tableName`
### WHERE
###   @1=5575 /* LONGINT meta=0 nullable=0 is_null=0 */
### SET
###   @28=3 /* TINYINT meta=0 nullable=0 is_null=0 */
###   @33='2021-10-11 15:00:23' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
# at 575858074
#211011 15:03:49 server id 1  end_log_pos 575858105 CRC32 0x080c9f8c 	Xid = 209544935
COMMIT/*!*/;
# at 575858105
#211011 15:03:49 server id 1  end_log_pos 575858170 CRC32 0x116d7859 	Anonymous_GTID	last_committed=218914	sequence_number=218915	rbr_only=yes

通过上面的日志可以看出field1字段被修改了三次，前两次为正常的修改操作，第三次导致问题的原因。第二次修改成的值应该是我预期的结果，但因为第三次的事务field1字段的值又被修改成原来的值了。第三次事务的时间超过了三分多钟，这应该是程序中的问题。