作者:郭斌斌
爱可生 DBA 团队成员,负责项目日常问题处理及公司平台问题排查。
本文来源:原创投稿
一、背景
二、复现前提
三、复现准备
3.1 创建表、构造数据
mysql> create table t1(id int primary key,name varchar(10));
Query OK, 0 rows affected (0.02 sec)
mysql> insert into t1 values(1,repeat('a',10));
Query OK, 1 row affected (0.01 sec)
mysql> insert into t1 select (select count(1) from t1)+id,name from t1;
Query OK, 1 row affected (0.01 sec)
Records: 1 Duplicates: 0 Warnings: 0
………………
mysql> insert into t1 select (select count(1) from t1)+id,name from t1;
Query OK, 4194304 rows affected (57.75 sec)
Records: 4194304 Duplicates: 0 Warnings: 0复制
3.2 准备 Delete 800多万记录的 Binlog 文件


MySQL Binlog mysql-bin.000003 用于回灌测试
3.3 由于 Binlog 的回灌和造数是在同一个实例上,之前为了构建 Delete 800多万记录的 Binlog ,已经将数据删除,因此在进行 binlog 回灌前,需要使用之前造数的方法,重新造数

3.4 同一个实例上先进行了 Delete ,又重新构建新的数据。导致 Delete 操作的 GTID 要比重新造数操作的 GTID 小,为保证可以正常回灌,可以执行 reset master

四、复现测试
4.1 解析 MySQL Binlog mysql-bin.000003

4.2 导入解析文件

4.3 查看 processlist ,发现导入线程一直处于 Sleep 状态,现象跟客户描述契合。

4.4 随即中断导入操作,重新发起导入同时使用 strace 记录操作的行为。

4.5 通过观测产生的 strace.log ,发现两个 read 的时间间隔不固定,少的也需要140ms左右,而读取的大小却只有4k(4096),读取效率偏低。

五、分析
通过 Google 检索“MySQL Mem Load Slow”发现这是一个 BUG ,MySQL 5.7 Client 在读取较大事务(涉及多行操作)时,由于内存分配效率比较低,导致消耗大量的时间,已在 MySQL 8.0.13 中修复。

六、复测
6.1 Mysql 8.0.18 客户端进行 Binlog 解析文件的回灌,提示 MySQL Server has gone away

6.2 导数报错时数据库没触发重启,查看 error 日志,有如下报错:

6.3 调大 max_allowed_packet 配置后重新测试

6.4 观测 strace 日志,每次读取 Binlog 大小16M,远高于原来的4k

6.5 观测线程状态

6.6 观察执行耗时,MySQL 8.0.18 客户端导数时间变短,效率提升明显。

七、结论
参考链接
文章推荐:
技术分享 | MySQL Hang 了,如何快速分析 Call Stack 有效信息
社区近期动态

