作者：余振兴

爱可生 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 = 250Mbinlog_rows_query_log_events = 1

备注:尽管binlog记录的信息足够多,但当故障起因定位后,因为其并未记录对该操作的IP及用户信息,如果不开审计,也只能晓得产生了该行为,但无奈具体定位触发该行为的"人".

7. binlog解析技巧

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