生产问题（十六）数据丢失-mysql binlog排查

一、引言

最近作者遇到一个线上问题，是mysql 的数据丢失了，这里记录一下排查过程和binlog的分析。

二、问题

问题出现的表象是应用系统大量报错，各种空指针之类的，这种一看就不可能是代码发布的问题，原因一定在框架、网络或者数据层。

我们首先根据日志找到了报错数据，然后在查sqlserver的时候发现是有的，但是mysql里面没有数据。

这里要提一下作者这里的数据架构背景，目前是双引擎的，sqlserver和mysql同时双写，有一个公共组件进行写入和更新，所以我们第一想法是组件有问题。

三、排查

1、公共组件

我们首先联系了公共组件的人，询问有无相关发布，但是很明显没有，并且公共组件还找了日志截图

可以明显看到插入语句和更新语句都是有返回影响行数的，所以公共组件应该是没什么问题

这样的话，怀疑的方向就到了数据层，是不是mysql的库坏了，虽然很少见，但是开发团队多的确什么情况都有，隔壁的数据库经常出问题

2、数据库

在觉得数据库有问题之后，我们就找dba导出binlog查看，这里要知道一下mysql的写入顺序。作者之前写过文章，binlog是最后写入的，在undo、redo之后，所以看数据问题binlog就可以

https://blog.csdn.net/m0_69270256/article/details/128311652?spm=1001.2014.3001.5501

先看一个单子的binlog写入，由于需要隐藏信息，这里的表和字段都呗替换成虚拟的

begin代表事务开启，

end_log_pos 26：这表示事件在二进制日志文件中的结束位置是26。这个数字是一个字节偏移量，指示了下一个事件在日志文件中的起始位置。
CRC32 0xe1：这是一个循环冗余校验（CRC32）值，用于检测日志内容在存储或传输过程中是否发生了变化。0xe1是这个特定事件内容的CRC32校验和。
Query：这表明记录的事件类型是一个查询。在二进制日志中，可以记录多种类型的事件，例如Query（查询）、Xid（事务ID）、Table_map（表映射）等。
thread_id=666：这是执行查询的线程ID。在MySQL中，每个客户端连接都由一个线程处理，这个ID可以用来追踪是哪个线程执行了这个查询。
exec_time=0：这表示查询的执行时间是0秒。这个值通常用于性能分析，了解查询执行的耗时。
error_code=0：这表示查询执行时没有发生错误。0通常表示操作成功，非零值表示发生了错误。

重点在于Write_rows和commit，这代表数据肯定是插入了

Write_rows：这表明事件的类型是写入行操作。这意味着该事件包含了被插入到表中的行的信息。
table id 94：这标识了行被插入的表。表ID是二进制日志文件中唯一的数字标识符，用于将事件与特定的表关联起来。要知道这个ID指的是哪个表，您需要查看二进制日志中前面的Table_map事件，该事件将表ID映射到实际的表名。
flags: STMT_END_F：这是与事件相关联的一组标志。特别是STMT_END_F标志表明这个Write_rows事件标志着一个语句的结束。在二进制日志的上下文中，这意味着该事件是代表单个SQL语句的一系列事件中的最后一个。

BEGIN
/*!*/;
# at 572
#523 13:15:39 server id id1  end_log_pos pos1 CRC32 0x60a16a59   Rows_query
# /*Client[MSG_ID:msgid1]*/REPLACE INTO `product` (`id`,`product`) VALUES (1,'product1')
# at pos1
#523 13:15:39 server id id1  end_log_pos 22 CRC32 0xc3   Table_map: `msdb`.`product` mapped to number 94
# at 22
#523 13:15:39 server id id1  end_log_pos 23 CRC32 0xfb   Write_rows: table id 94 flags: STMT_END_F
### INSERT INTO `msdb`.`product`
### SET
###   @1=1 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2='uid1' /* VARSTRING(80) meta=80 nullable=0 is_null=0 */
###   @3='' /* VARSTRING(80) meta=80 nullable=0 is_null=0 */
# at 23
#523 13:15:39 server id id1  end_log_pos 24 CRC32 0xb1   Xid = 222
COMMIT/*!*/;
# at 24
# at 25
#523 13:15:39 server id id1  end_log_pos 26 CRC32 0xe1   Query  thread_id=666  exec_time=0  error_code=0

=134/*!*/;

如果是被回滚了，他应该是这样的，ROLLBACK标志会非常明显，所以一定不是回滚然后没有插入

BEGIN/*!*/;
# at 572
#523 13:15:39 server id id1  end_log_pos pos1 CRC32 0x60a16a59   Rows_query
# /*Client[MSG_ID:msgid1]*/REPLACE INTO `product` (`id`,`product`) VALUES (1,'product1')
# at pos1
#523 13:15:39 server id id1  end_log_pos 22 CRC32 0xc3   Table_map: `msdb`.`product` mapped to number 94
# at 22
#523 13:15:39 server id id1  end_log_pos 23 CRC32 0xfb   Write_rows: table id 94 flags: STMT_END_F
### INSERT INTO `msdb`.`product`
### SET
###   @1=1 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2='product1' /* VARSTRING(80) meta=80 nullable=0 is_null=0 */
# at 23
#523 13:15:39 server id id1  end_log_pos 24 CRC32 0xb1   Xid = 222
ROLLBACK/*!*/;
# at 24

而且后续还能看到更新这条数据的binlog，同样说明了数据是进入数据库的

BEGIN/*!*/;
# at 572
#523 13:15:39 server id id1  end_log_pos pos1 CRC32 0x60a16a59   Rows_query
# /*Client[MSG_ID:msgid1]*/UPDATE `product` SET `product`='product2' WHERE `id`=1
# at pos1
#523 13:15:39 server id id1  end_log_pos 22 CRC32 0xc3   Table_map: `msdb`.`product` mapped to number 94
# at 22
#523 13:15:39 server id id1  end_log_pos 23 CRC32 0xfb   Update_rows: table id 94 flags: STMT_END_F
### UPDATE `msdb`.`product`
### WHERE
###   @1=1 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2='product1' /* VARSTRING(80) meta=80 nullable=0 is_null=0 */
### SET
###   @1=1 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2='product2' /* VARSTRING(80) meta=80 nullable=0 is_null=0 */
# at 23
#523 13:15:39 server id id1  end_log_pos 24 CRC32 0xb1   Xid = 224
COMMIT/*!*/;
# at 24

既然数据有了，那有没有可能是被删除了，但是我们是没有物理删除的，也没有人提工单去手工删除，

再看看binlog找不到删除的语句，如果有应该会像下面的语句一样

但是binlog也不是准确的，这里说的不准确不是说mysql服务器的binlog不准确，而是dba提供的下载工具。这种下载工具一般是计算好文件偏移量，然后进行多线程读取，但是文件在不断写入又被读取，事关数据库也不会锁文件，这中间有offset偏移是很正常的，所以下载的文件流很容易丢失和读取偏移。

BEGIN/*!*/;
# at 572
#523 13:15:39 server id id1  end_log_pos pos1 CRC32 0x60a16a59   Rows_query
# /*Client[MSG_ID:msgid1]*/DELETE FROM `product` WHERE `id`=1 AND `product`='product1'
# at pos1
#523 13:15:39 server id id1  end_log_pos 22 CRC32 0xc3   Table_map: `msdb`.`product` mapped to number 94
# at 22
#523 13:15:39 server id id1  end_log_pos 23 CRC32 0xfb   Delete_rows: table id 94 flags: STMT_END_F
### DELETE FROM `msdb`.`product`
### WHERE
###   @1=1 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2='product1' /* VARSTRING(80) meta=80 nullable=0 is_null=0 */
# at 23
#523 13:15:39 server id id1  end_log_pos 24 CRC32 0xb1   Xid = 223
COMMIT/*!*/;
# at 24

到这里就有点坑了，不能纠结到底是不是binlog下载丢失，也有可能是就没有删除日志。好在后面又找到了一个两天前的老单子，在mysql对应bi 的数据库里面有数据，因为bi库都是T-1的，所以可以证明数据的确是被删除了

后面换方向排查db审批工单的确发现是被删除了，属于误操作删除

三、拓展

有的读者可能不太了解binlog，作者这里讲讲它的原理和使用

1、原理

日志格式：MySQL支持三种binlog格式：statement-based replication (SBR)，row-based replication (RBR)，和mixed-mode replication。SBR记录SQL语句，RBR记录行的变化，mixed模式根据操作自动选择SBR或RBR。
日志内容：binlog记录了所有修改数据库状态的SQL语句，如INSERT、UPDATE、DELETE，以及DDL语句如CREATE TABLE、ALTER TABLE等。
日志作用：
- 复制：在主从复制中，从服务器会读取主服务器的binlog来复制数据。
- 数据恢复：可以使用binlog来恢复因操作错误或其他原因丢失的数据。
- 审计：binlog可以用来审计数据库的变更历史。
日志索引：MySQL会维护一个binlog索引文件，记录所有binlog文件的列表。