[MYSQL] 从库 io_thread 接受binlog速度太慢?

导读

前两天遇到一个主从延迟问题, 准备修改下相关参数(slave_parallel_type,slave_parallel_workers)来处理. 在此之前得先在测试环境对比下修改前后的区别.

于是开发在测试发起了相关测试, 从库的延迟一路高歌猛进, 很好, 和生产差不多, 模拟出来了. 但是我当时有使用show processlist查看, 感觉sql线程比较闲, 明明延迟都那么大了. 却很少看到sql线程回放sql语句(binlog_rows_query_log_events=ON). 于是看了下relay log信息, 发现从库只有不到100MB的binlog和relay log; 主库那边已经产生了10+GB的日志啊, 查看从库接受的binlog位置还对应主库的第一个Binlog.

也就是说从库只收到了几十MB的主库日志.

分析过程

我们先来看下主从同步的逻辑: 主库发送binlog给从库的io_thread, io_thread写入relay log, 然后sql线程去回放相关relay log

现在的情况是 io_thread 接收binlog的速度就非常慢了, 还没到回放那一步.

怀疑网络问题

传得慢, 那当然首先怀疑是网络的问题了. 我们使用dstat发现网速只有100 KB/s

于是使用如下几种方式进行验证

# 使用scp验证网速
scp MASTER:/binlog  SLAVE/relay_log

# 使用wget验证3306附近端口的速度
wget MASTER:3307/binlog/xxxx

# 使用mysqlbinlog远程拉主库的binlog
mysqlbinlog --read-from-remote-server --raw --host=master --user='xx' --password='xx' --result-file=RELAY_DIR

上述验证下来速度均达到几百MB/s 这不但验证了网速, 还顺便验证了IO, 但均未发现异常. 一下就把路都走死了.(wget甚至能达到900MB/s)

堆栈分析

本来准备使用perf的, 但是遇到报错"Dazed and confueds. but tring to continue", 于是手动gdb

# 先找到io_thread的thread id
mysql -e 'select name,thread_os_id from performance_schema.threads where name like "%slave_io%"'

# gdb调试mysqld进程
gdb -p `pidof mysqld`
info threads  #查看进程信息
thread 33 # 切换到io_thread线程
bt # 查看堆栈信息

大概信息如下:

fsync()
os_file_fsync_posix()
os_file_flush()
...
MYSQL_BINLOG_COMMIT::commit
ha_commit_trans()

这明显是在提交的时候刷盘的啊. 尝试了好几次均为这种状态. 而且把sql_thread线程停了之后, 每次抓也是处于这个fsync阶段.

使用strace看下了也是主要是在write(relay log fd), 就又回到了IO问题上.

修改了relay_log_info_repository为FILE也不行.

万能的重启大法

遇事不决, 先重启.

于是重启了主从复制进程, 无果.

再重启了mysqld进程, 无果.

最后重启了OS, 还是TM的无果.

perf分析

万能的重启大法虽然失败了, 但是perf却可以使用了, 所以也不算完全失败.

于是我们使用如下命令采样2分钟并分析

# 采样
perf record -F 100 -p `pidof mysqld` -- sleep 120

# 下载画图软件(可选)
wget https://github.com/brendangregg/FlameGraph/archive/refs/tags/v1.0.tar.gz
tar -xvf v1.0.tar.gz
cd FlameGraph-1.0

# 画图
FLAMEGRAPH_DIR='/root/flamegraph/FlameGraph-1.0'
perf script -i perf.data  | ${FLAMEGRAPH_DIR}/stackcollapse-perf.pl | perl ${FLAMEGRAPH_DIR}/flamegraph.pl > perf_test_io_thread.svg

下图为模拟的, 非测试环境的.

实际情况干扰项会少很多

可以看到耗时是在两阶段提交刷盘上, 也就是还是卡在IO上.

再度怀疑IO

既然性能又回到IO上, 那我们就再次测下IO吧. 我们可以使用如下python脚本简单测试下IO

#!/usr/bin/env python

import time
import os

FILENAME = '/tmp/test_io_20250711.bin'
FILESIZE = 1*1024*1024*1024
BLOCKSIZE = 4*1024

data = b"x"*BLOCKSIZE
start_time = time.time()
with open(FILENAME,'wb') as f:
	for x in range(FILESIZE//BLOCKSIZE):
		f.write(data)
		f.flush()
		os.sync()
stop_time = time.time()
print('FILE SIZE:',FILESIZE,'COST TIME:',round(stop_time-start_time,2),'sec')
print('IOPS:',round(FILESIZE//BLOCKSIZE//(stop_time-start_time),2) )
print('RATE:',round(FILESIZE/(stop_time-start_time),2))

这里是基于4KB来算的, 因为解析binlog发现很多小事务, 平均下来4KB左右.

我这IOPS虽然有1400, 但实际场景是远不到这个值的. 也就是说iops很低, 刷盘又很频繁, 于是就刷不过来了.

主库也测试过, 和从库IOPS差不多.

关双1

既然刷盘刷得慢, 那就不刷盘了! 于是我们直接关闭双1

set global innodb_flush_log_at_timeout = 0;
set global sync_binlog = 0;

不需要重启, 直接观察dstat, 发现网速飙到了200+, 然后就没了(因为已经传输完了).

从库接受到事务后, 会更新mysql.slave_relay_log_info, 这张表是innodb表, 每次提交都得走双1. 浪费了为数不多的IOPS

延迟也很快降下来了(在双1关闭之后). 所以问题基本上算是结了.

总结

原因: 大量小事务 + 从库的低IOPS 导致本次从库的延迟增大.(刷盘刷得慢,网络接受得也就慢了).

解决方法: 关闭从库双1, 减少IO.

合并小事务为相对较大的事务理论上也是可行的, 但还在验证中. 合并为多大的事务合适呢? 我们可以通过上面测试iops的脚本来测试, 比如我的环境:

4KB每次IO的时候, 速度为:5.47 MB/s

4MB每次IO的时候, 速度为: 579.42 MB/s

20MB每次IO的时候, 速度为: 601 MB/s

40MB每次io的时候, 速度为: 568 MB/s

也就是每次刷盘在某个值的时候,io带宽能达到最大值. 具体多少得直接测试了. 不同的环境是不同的. 这样每次提交的事务都按照这个来的话, 理论上就能最大程度利用IO(这是针对于跑批之类的能改变事务大小的场景来说的. 觉得麻烦的话, 直接关从库的双1, 让OS去考虑吧.)

思考: 主库IOPS也是差不多啊, 为啥这么多小事务跑得还挺快的(相对于从库来说)?