记一次MySql服务器磁盘负载持续升高问题的优化

背景

新年上班第一天，还没来得及从过年的氛围中缓过劲来，就收到了某个接口A的大量警报。

分析过程

备注：基于保密考虑，后续相关数据和分析图都是基于事实上进行的模拟。

分析接口A

耗时总览

首先查看接口A的耗时图：

有以下几个关注点：

• 接口耗时之前稳定在50ms左右。
• 接口耗时从2月2日开始持续上升至200ms左右。
• 以上只是正常不报警的接口的耗时情况。
• 基于接口A的警报阈值为3s，也就是说，还有很多接口运行超过了3000ms。
• 在2月2日至2月1日左右，延时上升并不快，这是因为这短时间是新年，系统访问量很低。
• 新年导致系统访问量低，这也是为什么过年期间没收到警报而是上班第一天才收到的原因。

耗时详情

鉴于接口A耗时急剧上升，于是对接口A最近5次耗时超过100ms的运行情进行分析，得到分析结果如下：

序号	接口总耗时	调用接口B耗时	其余耗时
1	191	131	60
2	406	303	101
3	374	325	51
4	452	386	66
5	422	367	55

分析表格，可知：

• 接口A的耗时主要被内部调用接口B时占用。
  • 接口B是其他系统的某个接口。
  • 通过对之前的日志分析，发现正常情况下，接口B耗时是毫秒级别的。
  • 通过对耗时查过3s的调用记录进行分析，发现调用接口B就是造成接口耗时超过3s的真正原因。
  • 那么是什么原因导致了接口B耗时急剧上升呢？
• 接口A其他逻辑的耗时在可接受范围内，但是依然比之前正常情况下的平均50ms要高。
  • 也就是说，接口A耗时上升不仅仅是接口B点原因造成的。
  • 也就是说，因为某些原因，导致接口A和接口B都变慢了。

经过以上分析，发现接口A与接口B都变慢了，那么其他的接口呢？
继续分析了几个接口，发现这些接口的耗时都在增加，只是上升幅度有大有小。
正式因为接口A上升幅度最大且超出了警报阈值，所以表现出来的情况是，只有接口A进行了警报。

因此，有理由怀疑，不是某个接口出了问题，而是MySql出了问题。

分析MySql

分析连接情况

通过show processlist对当前连接线程进行查看，发现:

• 连接数维持在1500左右，而max_connections=4096，所以这不是问题。
• 没有持续Locked的连接，所以这不是问题。
• 有些连接耗时几千毫秒，但是随着时间推移，都会逐渐释放，不存在长期不释放的连接，所以这不是问题。

分析磁盘使用情况

通过df -h发现MySql所在磁盘的磁盘使用率为82%，不存在问题。

分析CPU负载

MySql的master和其中一个slave的最近一个月的cpu负载率如下图：

有以下几个关注点：

• 从1月26日开始，master服务器负载率开始上升，而slave一直很平稳，所以是master出了问题。
• master服务器的上升速率越来越快，说明导致出现此问题的原因会造成恶性循环，而非恒定影响。

继续对CPU负载率进行细化分析，精确到每天，其他大体形状进化过程如下图：

有以下几个关注点：

• 每天晚上11点左右，负载率开始下降，与实际业务相符，因为晚上11之后用户准备睡觉，系统访问人数急剧下降。
• 每天凌晨2点，负载率急剧上升，是因为2点会开启很多自动服务，进行大量的统计查询，这些查询都是重型SQL，对MySql造成压力很大。
• 正常情况下，负载率在临床5点6点左右就会降至谷值，因为此时自动服务基本都已处理完毕。
• 正常情况下，负载率在白天从6点左右至凌晨是一个M形状，这与白天用户的活动时间相符。
• 通过查看复杂渐变情况，发现凌晨2点的峰值越来越高，而且因自动服务造成的谷值时间也越来越晚，直到最后无法观测。
• 而且因为因自动服务造成的压力越来越大，造成白天的负载率也受到牵连，不再是M形状。

综上分析，因该是有什么原因，导致MySql服务在凌晨2点开始压力骤增。

而恰好，大部分自动服务都是凌晨2点钟开始运行的，所以有理由怀疑应该是自动服务造成的影响。

分析自动服务

由于历史原因，这个MySql服务集群对应的一系列服务，还没有进行底层的读写分离，只是规定了业务层次的读写分析约束。
这种约束是不能完全保证读写分离的，导致的结果就是有一部分自动服务的查询还是在主库上进行的。
而且自动服务一般都是比较复杂的查询，耗时很长，当多个复杂查询同时进行时，由于资源争夺，会导致每个查询特别耗时。
这也是所有接口的耗时都在或多或少上升的原因。

根据上述分析，对还在主库上的自动服务进行了排查，还真发现了一个超级慢的自动查询C。
自动查询C的SQL语句涉及了distinct、having、group by、count以及子查询，而且其中有个表数量级7300万。
继续对自动服务的日志进行分析，发现其查询耗时长，由几个月前的75分钟逐渐上升至400分钟。
也就是说：

• 刚开始的时候，自动服务C的执行时间是从凌晨2点，一直执行至凌晨3:15。
• 然后执行时间逐渐增长，最近一次的执行时间是从凌晨2点，一直执行至上午8:40。

根据上述执行时间的延长问题，很大可能问题就出在这个自动服务上。
那么为什么之前的几个月这个自动查询并不慢呢？继续把问题定位至查询的大表T上。

分析大表T

通过查询，发现这个大表T，几个月前的总记录条数约为4200万，然后持续增长至7300万。
MySql单表在5000万左右基本到达了单表的性能瓶颈，在7300万的表上进行这种超级复杂的查询肯定会出问题。

其实，这个表前端时间已经做了分表，但是由于涉及的业务太多了，所以有些历史复杂查询还在老表上执行，所以才会出现以下现象：

• 接口A变慢的主要原因是接口B，通过分析发现接口B也是在老表B上进行的复杂查询。
• 有很多接口或多或少的都收到了影响，延时上升幅度较大的接口，都是还没有完成分表改造的查询。

处理方案

临时方案

因为时间原因，无法对这个自动服务C的相关逻辑进行改造，因此进行了临时处理：查询切换至从库。
切换从库之后，经过一段时间的运行，发现cpu负载率确实降下来了，恢复到正常水平。
而且，对受影响的接口都进行了检查，发现这些接口的延时都已经恢复正常情况。

后续方案

后续会做以下几件事：

• 鉴于业务读写分离的现状，继续检查各自动服务，尽量将查询的自动服务迁移到从库。
• 继续进行分表改造工作，尽量减少对老表的操作。
• 对无论如何改造查询都很慢的服务进行换库，比方说迁移到ElasticSearch、Redis或者数据仓库上。

补充说明

现已经此慢查询迁移至了百度数据仓库Palo中，查询耗时降级为秒级。