被记大过了，一个操作把MySQL主从复制整崩了…… _MySQL

一、前言
【被记大过了，一个操作把MySQL主从复制整崩了……】最近公司某项目上反馈MySQL主从复制失败，被运维部门记了一次大过，影响到了项目的验收推进，那么究竟是什么原因导致的呢？而主从复制的原理又是什么呢？本文就对排查分析的过程做一个记录。
二、主从复制原理
我们先来简单了解下MySQL主从复制的原理。

文章插图
1.主库master 服务器会将 SQL 记录通过 dump 线程写入到二进制日志binary log中。
2.从库slave 服务器开启一个 io thread 线程向服务器发送请求，向主库master 请求 binary log 。主库master 服务器在接收到请求之后，根据偏移量将新的 binary log 发送给 slave 服务器。
3.从库slave 服务器收到新的 binary log 之后，写入到自身的 relay log 中，这就是所谓的中继日志。
4.从库slave 服务器，单独开启一个 sql thread 读取 relay log 之后，写入到自身数据中，从而保证主从的数据一致。
以上是MySQL主从复制的简要原理，更多细节不展开讨论了，根据运维反馈，主从复制失败主要在IO线程获取二进制日志binlog超时，一看主数据库的binlog日志竟达到了4个G，正常情况下根据配置应该是不超过300M 。

文章插图
三、binlog写入机制
想要了解binlog为什么达到4个G，我们来看下binlog的写入机制。
binlog的写入时机也非常简单，事务执行过程中，先把日志写到 binlog cache ，事务提交的时候，再把binlog cache写到binlog文件中。因为一个事务的binlog不能被拆开，无论这个事务多大，也要确保一次性写入，所以系统会给每个线程分配一个块内存作为binlog cache 。

文章插图

上图的write，是指把日志写入到文件系统的page cache，并没有把数据持久化到磁盘，所以速度比较快
上图的fsync，才是将数据持久化到磁盘的操作, 生成binlog日志中

生产上MySQL中binlog中的配置max_binlog_size为250M, 而max_binlog_size是用来控制单个二进制日志大小，当前日志文件大小超过此变量时，执行切换动作。,该设置并不能严格控制Binlog的大小，尤其是binlog比较靠近最大值而又遇到一个比较大事务时，为了保证事务的完整性，可能不做切换日志的动作，只能将该事务的所有$QL都记录进当前日志，直到事务结束。一般情况下可采取默认值。
所以说怀疑是不是遇到了大事务，因而我们需要看看binlog中的内容具体是哪个事务导致的。
四、查看binlog日志
我们可以使用mysqlbinlog这个工具来查看下binlog中的内容，具体用法参考官网：https://dev.mysql.com/doc/refman/8.0/en/mysqlbinlog.html 。
1.查看binlog日志
./mysqlbinlog --no-defaults ---output=decode-rows -vv /mysqldata/mysql/binlog/mysql-bin.004816|more
2.以事务为单位统计binlog日志文件中占用的字节大小
./mysqlbinlog --no-defaults ---output=decode-rows -vv /mysqldata/mysql/binlog/mysql-bin.004816|grep GTID -B1|grep '^# at' | awk '{print $3}' | awk 'NR==1 {tmp=$1} NR>1 {print ($1-tmp, tmp, $1); tmp=$1}'|sort -n -r|more

文章插图
生产中某个事务竟然占用4个G 。
3.通过start-position和stop-position统计这个事务各个SQL占用字节大小
./mysqlbinlog --no-defaults ---output=decode-rows --start-position='xxxx' --stop-position='xxxxx' -vv /mysqldata/mysql/binlog/mysql-bin.004816 |grep '^# at'| awk '{print $3}' | awk 'NR==1 {tmp=$1} NR>1 {print ($1-tmp, tmp, $1); tmp=$1}'|sort -n -r|more

文章插图
发现最大的一个SQL竟然占用了32M的大小，那超过10M的大概有多少个呢？
4.通过超过10M大小的数量
./mysqlbinlog --no-defaults ---output=decode-rows --start-position='xxxx' --stop-position='xxxxx' -vv /mysqldata/mysql/binlog/mysql-bin.004816|grep '^# at' | awk '{print $3}' | awk 'NR==1 {tmp=$1} NR>1 {print ($1-tmp, tmp, $1); tmp=$1}'|awk '$1>10000000 {print $0}'|wc -l

文章插图
统计结果显示竟然有200多个，毛估一下，也有近4个G了.
5.根据pos, 我们看下究竟是什么SQL导致的
./mysqlbinlog --no-defaults ---output=decode-rows --start-position='xxxx' --stop-position='xxxxx' -vv /mysqldata/mysql/binlog/mysql-bin.004816|grep '^# atxxxx' -C5| grep -v '###' | more