复制延迟问题排查 一、常见原因 产生延迟的根本原因在于MySQL复制是基于逻辑日志binlog进行异步的数据复制的,事务的binlog日志要通过网络传输到从库,再在从库上完成一次逻辑的回放,各个阶段的耗时都有可能被放大,导致延迟。在我们的经验中,诱发延迟的常见原因有: 1.主从配置不一致,从库配置较低导致回放过慢 2.主从库之间的网络带宽太低 3.主库的QPS过高(应用负载高),从库回放时无法达到主库的并发程度 4.主库对无主键的表做全表更新或全表删除操作,row-based binlog replication 时,从库回放这个事务时会做n次全表扫描,n为表的总行数(常见于业务数据库处理时临时表的清理) 5.主库在某时间段执行大量的大事务(大量的插入,更新,删除操作,如跑批操作) 6.主库在对表做DDL操作 7.从库备份触发Waiting For Global Read Lock导致从库回放线程在备份时间内无法回放数据 8.从库没有配置并行复制 二、IO线程排查 排查IO线程是否存在延迟主要是判断从库接收到的binlog(从库叫Relay Log)是否与主库当前最新的binlog保持一致或者仅仅细微的差别,可以通过以下方式分析 1. 获取主库当前的binlog name、position、executed_gtid_set root@localhost[(none)]> show master statusG *************************** 1. row *************************** File: mysql-bin.000001 Position: 149654676 Binlog_Do_DB: Binlog_Ignore_DB: Executed_Gtid_Set: 56929ffe-5d09-11ea-bb4e-02000aba3da2:1-67963 2. 获取从库当前读取的binlog位置 root@localhost[(none)]> show slave statusG *************************** 1. row *************************** Slave_IO_State: Waiting for master to send event Master_Host: 10.186.61.162 Master_User: repl Master_Port: 3306 Connect_Retry: 60 Master_Log_File: mysql-bin.000001 Read_Master_Log_Pos: 149654676 Relay_Log_File: mysql-relay.000003 Relay_Log_Pos: 149654881 Relay_Master_Log_File: mysql-bin.000001 Slave_IO_Running: Yes Slave_SQL_Running: Yes ... 输出内容过多,部分输出已省略 Seconds_Behind_Master: 1000 ... 输出内容过多,部分输出已省略 Retrieved_Gtid_Set: 56929ffe-5d09-11ea-bb4e-02000aba3da2:1-67963 Executed_Gtid_Set: 56929ffe-5d09-11ea-bb4e-02000aba3da2:1-42311 3. 结果比对 最后通过对比主从参数是否有明显的差异来判断IO线程是否有延迟。 主库: File、Position、Executed_Gtid_Set 从库: Master_Log_File 、Read_Master_Log_Pos、Retrieved_Gtid_Set 如示例中从库读取的binlog位置和主库当前最新的binlog位置均是mysql-bin.000001,Position点均为149654676,表示当前IO线程无延迟,需做进一步分析SQL线程情况。 也可通过主库中标红的Executed_Gtid_Set(主库当前已提交的事务GTID集合)和从库中Retrieved_Gtid_Set(从库读取到的事务GTID集合)的差值来做比。 三、SQL线程排查 主从延迟大部分原因在于从库的SQL线程回放过慢,这也是我们主要关注的排查点。 查看从库的复制状态 root@localhost[(none)]> show slave statusG *************************** 1. row *************************** Slave_IO_State: Waiting for master to send event Master_Host: 10.186.61.162 Master_User: repl Master_Port: 3306 Connect_Retry: 60 Master_Log_File: mysql-bin.000001 Read_Master_Log_Pos: 149654676 Relay_Log_File: mysql-relay.000003 Relay_Log_Pos: 149654881 Relay_Master_Log_File: mysql-bin.000001 Slave_IO_Running: Yes Slave_SQL_Running: Yes ... 输出内容过多,部分输出已省略 Exec_Master_Log_Pos: 148451632 Seconds_Behind_Master: 1000 Slave_SQL_Running_State: system lock ... 输出内容过多,部分输出已省略 Retrieved_Gtid_Set: 56929ffe-5d09-11ea-bb4e-02000aba3da2:1-67963 Executed_Gtid_Set: 56929ffe-5d09-11ea-bb4e-02000aba3da2:1-42311 关注示例中的两组状态:Master_Log_File、Read_Master_Log_Pos、Relay_Master_Log_File、Exec_Master_Log_Pos、Retrieved_Gtid_Set、Executed_Gtid_Set a) binlog位置 读取到的主库binlog的位置: Master_Log_File: mysql-bin.000001 Read_Master_Log_Pos: 149654676 从库当前回放的位置(对应在主库的binlog位置): Relay_Master_Log_File: mysql-bin.000001 Exec_Master_Log_Pos: 148451632 这里只差了1203044个position,没有binlog级别的落后,说明延迟不特别大。 b) 事务的GTID集合 读取到的主库的事务GTID集合: Retrieved_Gtid_Set: 56929ffe-5d09-11ea-bb4e-02000aba3da2:1-67963 从库已经回放的事务GTID集合: Executed_Gtid_Set: 56929ffe-5d09-11ea-bb4e-02000aba3da2:1-42311 这里说明从库上总共读取到了67963个事务的binlog,但是只回放到第42311个事务,如果IO线程没有延迟,则从库与主库相比延迟了25652个事务。 查看从库单位时间内的回放速度 在这个阶段可以反复执行show slave statusG,查看从库SQL线程位置的变化,或者通过这样的SQL查看一段时间内从库回放了多少个事务: mysql> select @@global.gtid_executed;select sleep(60);select @@global.gtid_executed; 如果Executed_Gtid_Set或者gtid_executed无变化,则说明从库卡在某个大事务上,60s都没有回放完,需要解析binlog查看回放的事务具体操作。 如果Executed_Gtid_Set有变化,但十分缓慢,比如60s统计内只回放了100个事务,可能也存在较大的事务,或者这批事务没有并发回放,也需要解析binlog进一步分析。当然也可能是从库服务器IO负载高、服务器配置低等原因。 如果统计到这60s内回放事务非常多,则说明当前位置回放速度正常,延迟可能是之前的事务导致的,而且主库QPS较高产生了较多的binlog,堆积到现在。这种情况可以持续观察,应该会慢慢的消除延迟。 解析主库binlog 如果从库回放的速度很慢,甚至slave_sql线程长时间停滞在一个位置,则我们需要根据这个位置去主库上解析binlog,分析这个位置是什么事务。 从show slave status输出中,找出这个几个位置: Relay_Master_Log_File: mysql-bin.000001 Exec_Master_Log_Pos: 148451632 Executed_Gtid_Set: 56929ffe-5d09-11ea-bb4e-02000aba3da2:1-42311 然后到主库上,解析mysql-bin.000001中从库正在回放的56929ffe-5d09-11ea-bb4e-02000aba3da2:42312这个事务,42312即42311的下一个事务: mysqlbinlog -vv --include-gtids='56929ffe-5d09-11ea-bb4e-02000aba3da2:42312' mysql-bin.000001|grep -v "# at"|less 注意要开启binlog_rows_query_log_events参数(意思为row格式时,binlog会以注释的形式记录具体的SQL语句,方便DBA排查问题), 进一步判断该事务中涉及的DML操作数量(是否为大事务): mysqlbinlog -vv --include-gtids='56929ffe-5d09-11ea-bb4e-02000aba3da2:42312' mysql-bin.000001|egrep "### UPDATE|### DELETE|### INSERT"|wc -l 最后附带一个binlog分析统计命令,可统计指定binlog中DML操作的数量: mysqlbinlog --no-defaults --base64-output=decode-rows -v -v mysql-bin.000001| awk '/###/ {if($0~/UPDATE|INSERT|DELETE/)count[$2" "$NF]++}END{for(i in count) print i," ",count[i]}' | column -t | sort -k2nr 三、解决方法 通用方法 针对MySQL复制延迟的问题,在选择硬件配置、存储引擎,设计业务逻辑和MySQL参数配置方面应使用以下指导思想,下列方法更多的是预防复制延迟的出现,在平时的巡检过程中,应该时刻关注客户现场的相关配置,例如是否有非innodb的表,是否没有开启并行复制,业务中是否存在大事务等等。 1.保持主从配置一致,也有利于主从切换后性能不会出现明显下降 2.开启并行复制等提升复制效率的参数,如下 slave-parallel-type=LOGICAL_CLOCK slave-parallel-workers=16 master_info_repository=TABLE relay_log_info_repository=TABLE relay_log_recovery=ON 3.确保所有表都有主键且全表清除使用truncate操作 4.将批量操作中大事务拆分为小事务执行,充分利用MySQL并行复制特性提升回放效率 5.使用gh-ost或POSC工具执行DDL,增加DDL的执行时间但减缓主从延迟问题 6.保证数据库中表的存储引擎为InnoDB,减少备份锁定时间 7.MySQL8.0版本的新特性中推出了binlog压缩功能,可降低带宽的消耗(新特性待验证) 临时方法 在主从复制延迟已经很严重的情况下,可使用如下方法来降低复制延迟,需要注意的是,在复制延迟的问题解决后,务必记得将大部分参数还原到原先的配置(以数据安全性为主的配置),并根据通用方法的思想来排查导致复制延迟问题的具体原因,并对症下药。 修改innodb_flush_log_at_trx_commit参数 此参数设置为0时表示MySQL会将日志缓冲区中的数据每秒一次地写入日志文件中,并且日志文件的刷盘操作同时进行。该模式下在事务提交的时候,不会主动触发写入磁盘的操作,效率最高,但是安全性也比较低,可能会丢失数据; mysql> SET @@GLOBAL.innodb_flush_log_at_trx_commit = 0; 修改sync_binlog参数 修改binlog的刷盘时机,当sync_binlog=0时,事务提交之后,MySQL不做fsync之类的磁盘同步指令刷新binlog_cache中的信息到磁盘,而让Filesystem自行决定什么时候来做同步,或者cache满了之后才同步到磁盘,这个是性能最好的。 mysql> SET @@global.sync_binlog = 0; 增加从库的change buffer缓冲池比例 innodb_change_buffer_max_size控制着change buffer的大小,默认为buffer pool的25%,最大可以设置为50% mysql> set global innodb_change_buffer_max_size = 50;