关于binlog:故障分析-MySQL-数据丢失事件之-binlog-解析应用一则

作者：余振兴

爱可生 DBA 团队成员，相熟 Oracle、MySQL、MongoDB、Redis，最近在盘 TiDB，善于架构设计、故障诊断、数据迁徙、灾备构建等等。负责解决客户 MySQL 及我司自研 DMP 数据库治理平台日常运维中的问题。热衷技术分享、编写技术文档。

本文起源：原创投稿

* 爱可生开源社区出品，原创内容未经受权不得随便应用，转载请分割小编并注明起源。
事件背景

事件背景

客户反馈在晚间数据跑批后, 查问相干表的数据时, 发现该表的局部数据在数据库中不存在, 从利用跑批的日志来看, 跑批未报错, 且可查到日志中明确显示过后那批数据已插入到数据库中, 须要帮忙剖析这批数据失落的起因。

备注: 思考信息敏感性, 以下剖析场景测试环境模拟, 相干数据做以下阐明

• 波及的库表为 demo.t_dba_info 表
• 失落的数据为 insert into t_dba_info(name,age) values('zhenxing',20); 这条记录

故障剖析

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

显然, 数据的确如客户所说, 在数据库中不存在

2. 确认该条数据失落的工夫区间并解析 binlog

这里我为模仿环境, 间接在主库解析, 生产环境倡议都在从库解析防止对主库造成影响

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 -vv ${binlog}|grep -iEw "zhenxing"
done

能够看到咱们通过解析并搜寻 zhenxing 这条记录, 的确发现数据插入了数据库中, 所以接下来从惯例的思路来说咱们只须要持续解析 binlog, 找到是否有对该条记录做 DELETE 或UPDATE操作即可

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

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

## 这里我通过已知的故障工夫区间将波及的 binlog 列出来做循环解析
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 --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

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

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

5. 排除一些非凡操作的可能性

1. 在插入这条数据时, 主库 binlog 明确有记录, 那是否有可能在删除这条记录时做了 set session sql_log_bin=off 不记录 binlog

   • 这个只需在从库查问下这条记录是否存在即可初步排除, 客户生产环境是一主多从的架构, 从库均没有这条记录存在, 可能性被排除

2. 有没有可能这张表除了 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 做具体解析, 失去以下信息

   #211211 14:52:47 truncate table t_dba_info
   #211211 14:53:00 insert into t_dba_info(name,age) values('zhenxing',20)
   #211211 14:53:18 truncate table t_dba_info

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

6. 故障总结

本文是对 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 及用户 信息, 如果不开审计, 也只能晓得产生了该行为, 但无奈具体定位触发该行为的 ” 人 ”.

7. binlog 解析技巧

1. 尽可能在从库解析, 防止对主库造成影响
2. 先粗略定位波及相干的库表操作的 binlog, 再独自解析对应的 binlog 中的数据
3. 在解析 DDL 时无需加 - v 输入详细信息(放慢解析速度)
4. 如果开启了 binlog_rows_query_log_events 参数, 须要用 -vv 参数才可显示具体的 SQL 语句