事件背景
客户反馈在晚间数据跑批后,查询相关表的数据时,发现该表的部分数据在数据库中不存在
从应用跑批的日志来看,跑批未报错,且可查到日志中明确显示当时那批数据已插入到数据库中 需要帮忙分析这批数据丢失的原因。
备注:考虑信息敏感性,以下分析场景测试环境模拟,相关数据做以下说明
- 涉及的库表为 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 语句
