当前位置：首页 > news >正文

MySQL 数据”丢失”事件之 binlog 解析应用

news 来源：原创 2025/5/16 21:24:36

事件背景

客户反馈在晚间数据跑批后,查询相关表的数据时,发现该表的部分数据在数据库中不存在
从应用跑批的日志来看,跑批未报错,且可查到日志中明确显示当时那批数据已插入到数据库中需要帮忙分析这批数据丢失的原因。

备注:考虑信息敏感性,以下分析场景测试环境模拟,相关数据做以下说明

涉及的库表为 demo.t_dba_info 表
丢失的数据为 insert into t_dba_info(name,age) values(‘zhenxing’,20);这条记录

故障分析

1. 先登录数据库确认该条记录是否存在

select *from t dba info where name='zhenxing' and age=20;
Empty set(0.0004 sec)#显然,数据确实如客户所说,在数据库中不存在

2. 确认该条数据丢失的时间区间并解析 binlog

INLOG_LIST='mysql-bin.000002 mysql-bin.000003 mysql-bin.000004 mysqlbin.000005 mysql-bin.000006 mysql-bin.000007'
for binlog in ${BINLOG_LIST}
do
echo "====== ${binlog}"
mysqlbinlog -vv ${binlog}|grep -iEw "zhenxing"
done
#这里我为模拟环境,直接在主库解析,生产环境建议都在从库解析避免对主库造成影响

在这里插入图片描述

可以看到我们通过解析并搜索 zhenxing 这条记录,确实发现数据插入了数据库中,所以接下来从常规的思路来说我们只需要继续解析 binlog,找到是否有对该条记录做 DELETE 或 UPDATE 操作

3. 解析 binlog 查看对这张表的修改操作

过滤出哪些 binlog 对该表做了 DELETE 或 UPDATE

BINLOG_LIST='mysql-bin.000002 mysql-bin.000003 mysql-bin.000004 mysqlbin.000005 mysql-bin.000006 mysql-bin.000007'
for binlog in ${BINLOG_LIST}
do
echo "====== ${binlog}"
mysqlbinlog --no-defaults --base64-output=decode-rows -
vv ${binlog} | awk '/###/ {if($0~/UPDATE|INSERT|DELETE/)count[$2" "$NF]++}END{for(i in
count) print i,"\t",count[i]}' | column -t | sort -k2nr|grep -i t_dba_info
done

在这里插入图片描述

通过解析 binlog 可以看到,对该表的操作只有 mysql-bin.000006 这个 binlog 文件有 2 次 UPDATE 操作,其他都是 INSERT,接下来我们只需要继续解析这个 mysql-bin.000006 文件并搜索看是否对 zhenxing 这条记录是否做了修改即可

4. 解析定位的 binlog

 [root@10-186-61-100 binlog]# mysqlbinlog -vv mysql-bin.000006|less#用最简单的命令直接解析并搜索对 demo.t_dba_info 表插入的 zhenxing 这条记录

在这里插入图片描述

通过解析发现这个 binlog 文件做对 demo.t_dba_info 表的 UPDATE 操作并不是针对 zhenxing 这条记录的, 分析到这里发现比较迷惑了,数据明明插入了,也没做修改怎么就不见了,难道做了一些特殊操作

5. 排除一些特殊操作的可能性

在插入这条数据时,主库 binlog 明确有记录,那是否有可能在删除这条记录时做了 set session sql_log_bin=off 不记录 binlog
- 这个只需在从库查询下这条记录是否存在即可初步排除,客户生产环境是一主多从的架构,从库均没有这条记录存在, 可能性被排除
有没有可能这张表除了 DML 行为,还有 DDL 行为,如重建了,但重建后这批数据没有被重新插入该表,于是尝试解析binlog 看对该表的 DDL 操作行

BINLOG_LIST='mysql-bin.000002 mysql-bin.000003 mysql-bin.000004 mysql-bin.000005 
mysql-bin.000006 mysql-bin.000007'
for binlog in ${BINLOG_LIST}
do
echo "====== ${binlog}"
mysqlbinlog ${binlog}|egrep -iEw "truncate|create|drop"
done

在这里插入图片描述发现了一些端倪,在 mysql-bin.000004 中有对该表的 2 次 truncate 操作,等等,好像发现了什么,那条丢失的数据也是在这个 mysql-bin.000004 文件中,梳理下逻辑,难道那条记录在 2 次 truncate 之间,于是单独对这个binlog 做详细解析,得到以下信息

truncate table t_dba_info
insert into t_dba_info(name,age) values('zhenxing',20)
truncate

到此基本了解了这条记录为何会诡异丢失了,与客户确认跑批灌数据的逻辑,了解到会对该表做 truncate,但由于误操作,在跑批开始后,又触发了一轮 truncate 行为,导致已经插入到该表的部分数据再次被清理了,也就导致了在解析 binlog 时部分记录丢失了,但并未观测到有删除的行为,而是被 truncate 方式清理。

故障总结

本文是对 binlog 解析的一个实践案例,binlog 记录的信息非常多,可以对 binlog 进行不同维度的解析,同时binlog 在线上环境的配置使用上也有着一些技巧,如本案例中,线上环境因为是规范化部署,参数设置合理,不会由于单个 binlog 文件过大导致 binlog 解析时间过长,以及如 binlog_rows_query_log_events 参数的开启,使得在 row 模式下也可以明确记录下具体的 SQL语句

max_binlog_size = 250M
binlog_rows_query_log_events = 1

虽然 binlog 记录的信息足够多,但当故障原因定位后,由于其并未记录对该操作的 IP 及用户信息,如果不开审计,也只能知道发生了该行为,但无法具体定位触发该行为的"人"。

binlog 解析技巧

1．尽可能在从库解析,避免对主库造成影响
2．先粗略定位涉及相关的库表操作的 binlog,再单独解析对应的 binlog 中的数据
3．在解析 DDL 时无需加-v 输出详细信息(加快解析速度)
4．如果开启了 binlog_rows_query_log_events 参数,需要用-vv 参数才可显示具体的 SQL 语句

事件背景

故障分析

1. 先登录数据库确认该条记录是否存在

2. 确认该条数据丢失的时间区间并解析 binlog

3. 解析 binlog 查看对这张表的修改操作

4. 解析定位的 binlog

5. 排除一些特殊操作的可能性

故障总结

binlog 解析技巧

相关文章：