一、引言
最近作者遇到一个线上问题,是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文件的列表。
2、操作
-
启用binlog:在my.cnf(或my.ini)配置文件中设置log_bin参数来启用binlog。
-
查看binlog:可以使用SHOW BINARY LOGS命令查看当前的binlog文件列表。
-
读取binlog:使用mysqlbinlog工具可以读取和解析binlog文件。
-
刷新binlog:使用FLUSH LOGS命令可以关闭当前的binlog文件并开启一个新的binlog文件。
-
清理binlog:可以设置expire_logs_days参数来自动删除旧的binlog文件,或者使用PURGE BINARY LOGS命令手动删除。
3、使用经验
-
选择合适的日志格式:根据应用场景选择SBR、RBR或mixed模式。RBR更精确但可能产生更大的日志文件,SBR更易读但在某些情况下可能导致数据不一致。
-
监控binlog空间:binlog可能会占用大量磁盘空间,需要定期监控和清理。
-
binlog备份:定期备份binlog文件,以便在需要时进行数据恢复。
-
安全考虑:binlog中可能包含敏感信息,需要确保binlog文件的安全。
-
性能影响:虽然binlog对性能有一定影响,但通常这种影响是可以接受的。如果性能是关键考虑因素,可以考虑使用SSD来存储binlog文件。
-
使用mysqlbinlog工具:熟悉mysqlbinlog工具的使用,它可以帮助你解析、过滤和应用binlog事件。
-
测试恢复流程:定期测试使用binlog的数据恢复流程,确保在紧急情况下能够快速有效地恢复数据。
四、总结
业务场景,读者们和作者可能不一样,但是这个排查思路和binlog分析都是可以学习的经验。