首先还是给出我见过的一些延迟可能:
- 大事物延迟 延迟略为2*执行时间 状态为:reading event from the relay log
- 大表DDL延迟 延迟略为1*执行时间 状态为:altering table
- 长期未提交的事物延迟,会造成延迟的瞬时增加
- 表上没有主键或者唯一键 状态为:system lock 或者 reading event from the relay log
- innodb层锁造成延迟 状态为:system lock 或者 reading event from the relay log
- 从库参数设置如sync_binlog,sync_relay_log,innodb_flush_log_at_trx_commit等参数
一、故障描述
本案例是一个朋友的,从各方面进行展示故障
按照他的描述是在主库进行了大量形如delete from where col='';的操作,每次delete会删除大量的行。主库删除并不慢,但是从库追不上。
下面是现象:
- 延迟较大且无好转迹象
- 系统整体负载不高但是mysqld进程100%
- 无I/O压力
- 有大事物的存在
这里这个5G是binlog的拷贝。
二、故障初次分析
首先我们要明白没有I/O压力代表了什么,没有I/O压力代表了我们常说的fsync没有压力,对应的不会是下面几个参数的问题:
- sync_binlog
- sync_relay_log
- innodb_flush_log_at_trx_commit
也就是跟I/O相关的调整我们是不需要考虑的。
我们再来看CPU的问题,用top -HU可以看到线程的资源消耗如下:
我们可以清楚的看到某个MySQL线程耗用CPU为100%,因为是5.7我们可以方便的使用语句
select a.thd_id,b.THREAD_OS_ID,a.user ,a.conn_id,b.TYPE,a.source,a.program_name from sys.processlist a,performance_schema.threads b where b.thread_id=a.thd_id;
找到MySQL线程和操作系统的对应关系如下:
我们可以清楚看到是我们的SQL_THREAD,所以我们找到的根源是SQL_THREAD耗用了过多的CPU资源但是I/O并不是问题。
三、故障再次分析
一般来讲我们遇到SQL_THREAD可能伴随着I/O问题,但是这里并没有,所以瓶颈可能在缓存数据的查找方面。我们使用perf进行一下分析排名靠前的如下:
其中btr_search_guess_on_hash适合AHI自适应的hash索引相关的函数,而rec_get_offsets_func是对索引的每个flied进行定位的函数(当然我也没仔细看过源码只是看了一下所在的文件位置和函数描述信息),也就是他们貌似都是二级索引数据的查找有关,我们再来看这个表的表结构如下:
我们发现这个表除了二级索引并没有主键,问题基本已经定位,也就是我开始给除的延迟中的一条:
- 表上没有主键或者唯一键 状态为:system lock 或者 reading event from the relay log
所以原因可能就是,因为没有主键或者唯一键,event回放的时候使用到了二级索引让回放速度慢且进行了大量的内存数据查找造成了CPU 100%而没有I/O的现象。
四、问题解决
也就是对本表加一个自增字段作为主键,速度马上提高了。当然这个解决办法其实我很最早就猜测到了,但是我想尽量找到为什么会这样。perf中的函数具体的逻辑等我学习AHI的在分析。呵呵呵呵!本次分析中唯一的遗憾是没有pstack栈帧,否则会更加清晰和有力。