问题表象
在24年初有一个日经问题困扰着我们,每到正点03分DB的CPU开始打满,持续1分钟又恢复正常水平。但由于日常业务交付压力较大且权限限制没有登录DB主机的权限,大家也就得过且过一直没有去认真排查。直到某天我来兴趣了也有时间了,就想起这个问题开始深入排查一下尝试解决。
排查-可能的问题点
这种一看周期性非常规律的CPU打满,又很快回落到正常水平的现象,有经验的就会猜到是定时任务导致的。的确这是一个大概率的猜测方向。但还有另一个可能,在做活动也会有周期性的流量暴增情况,但我们系统是to b的业务系统所以排除。
结合定时任务分析有2种可能,这个从Job的执行时间频率上能看出来。然后通过业务逻辑大致可以知道哪一个Job是比较重的结合时间重点排查。在我们系统中有一个核心业务,每小时会根据后台配置的计划规则,解析计划下发巡检任务给一线人员执行,这个业务逻辑会短时间5分钟内下发几千条任务。每一条任务涉及的IO会很多,可能十几次?
- 整点下发任务
- 整点03分更新任务状态
首先排查是否任务下发导致的CPU升高。但是很快通过SQL统计每个时间段的下发任务数量对比,可以排除这个问题。任务大多数是凌晨0点下发。早上9点-11点下发的任务少数。所以不太可能是任务下发导致CPU升高。再查看凌晨0点,MySQL CPU只有18%左右,相差甚远。
那么继续排查另一个方向:任务的状态修改Job。结合整点03分DB的CPU飙高,推测taskStatusUpdate定时任务导致的概率大。这个任务共有3部分。
从数据量上看,任务关闭和任务预警的数据量都比较少。不太可能是瓶颈。任务开启的数据量较多,概率比较大。着重看下任务开启的方法。
首先是一个没有索引的全表扫表。看日志这个SQL大概1~2s左右。从“开启任务数量”的日志,到“开启任务成功”的日志间隔大概25s左右。佐证这个方法耗时比较慢,可能导致DB CPU飙高。方法里面涉及到IO的以下方法。
各位读者看到下面的IO查询,可以根据给出的信息推理下哪一个是根因导致CPU升高?亦或是组合原因引起的? 下文会给出每一步的耗时日志证明本次的优化的确是优化到问题根因上了。一开始我认为是组合原因引起的,由于a表数据最大1000w以上,且二级索引的区分度比较低0.13左右,结合下面的接近700w的表两次IO更新,如果更新数据量比较大的话是可能导致CPU升高的。
// 1000w数据,workorder_id二级索引区分度13%
List<A> a = aService.list(...);
// 688w数据,主键。这步可省
List<B> bList = bService.listByIds(idList);
// 688w数据,主键
bService.updateBatchById(bList);
// 480w,主键
cService.updateBatchById(cList);
// 186w,task_id二级索引区分度13%
List<D> dList = dService.list(...);
// 网络IO+auth磁盘IO,auth主键,registration_id全表扫描
pushService.push(pushDTO);
但是最后根据打的耗时日志发现居然是最后的pushService.push方法耗时最高且它就是根因,占到整个方法的90%耗时。下图贴出每一步方法的耗时日志可以对应这里的伪代码。
// 1000w数据,workorder_id二级索引区分度13%
// cost 10ms量级
List<A> a = aService.list(...);
// 688w数据,主键。
// 优化后这个查询被省略了 0ms
List<B> bList = bService.listByIds(idList);
// 688w数据,主键
// cost 1~2s量级
bService.updateBatchById(bList);
// 480w,主键
// cost 1s量级
cService.updateBatchById(cList);
// 186w,task_id二级索引区分度13%
// 100ms量级
List<D> dList = dService.list(...);
// 网络IO+auth磁盘IO,auth主键,registration_id全表扫描
// 导致CPU打满的原因,耗时占总体90%
pushService.push(pushDTO);
优化方案
OK,提前破案了,把原因告诉大家了。我按照以下方法慢慢定位出pushService慢的原因。
- 每个步骤打cost日志
- 每个IO按需查询
- A表优化索引,避免回表
- 节省不必要的IO查询
- 优化registration_id查询SQL,避免全表扫描
但是为什么pushService的推送会引起CPU的打满?这是一个给用户推送app push的方法,正常情况下不会和DB CPU产生联想。
这里面其实就有一个比较隐蔽的慢查询场景,其实我总结身边80%的数据库CPU打满都和慢SQL有关。因为慢SQL会对表进行大量扫描,通常会将数据页读到Buffer Pool中然后进行大量内存读写和计算,有可能一条慢SQL要遍历几十万~几百万的数据行才能找到目标行。这个过程会大量消耗CPU时间,如果短时间这种慢SQL并发达到一定阈值,MySQL的链接数和CPU就都会被消耗完。
回到pushService排查,里面有一个对user表的查询,需要根据registration_id查出本次app push的目标用户,registration_id是没索引的。而这张表数据并不大只有25w的数据量。找DBA要了CPU打满时间段的慢SQL日志,查找果然这条SQL在其中,并且统计数量在1分钟内有几百条查询,每一条查询也消耗了3~4秒时间,检索22万行数据最终返回32行给客户端。
临时解决方案是给registration_id字段加普通索引,由于表数据量不大且MySQL版本5.7+,DDL是在线替换的,锁表时间很短,期间不阻塞DML语句,直接加索引。
结果回顾
加完索引后,观察下一次任务状态变更Job,MySQL服务器的CPU明显降下来了,从100%降到30~40%,并且持续时间较短。上面提到的加索引是临时解决方案,简单粗暴但有效。但是仍有优化空间,对循环调用查user表可以加缓存或者该批量查询。但是任务变更Job导致的cpu 100%下来后,就凸显了另一个Job的尖刺40~50%左右。
总结
全表扫描的SQL对DB的cpu影响比较高,如果偶发的并不多的请求数量,在监控层面看不出来影响,且单条SQL执行也很快。但是并发多了之后,短时间堆积的慢SQL就会明显占用DB资源。