记一次 CPU 持续增长的问题解决

背景

线上服务在一次功能变更上线的约一周后, 出现了服务超时问题

直观考虑

Q1: 由于服务本身定位是下游的保障服务, 服务质量受上游流量影响, 对上流的突发大流量请求, 偶尔会有超时情况出现;

A1: 查看上游请求流量, 发现在时间上吻合, 确实存在突增的上游流量, 查看此时流量已经下降, 继续观察超时发生情况;

约几分钟后, 发现超时请求量下降, 但仍然存在。和前几天同时段相比, 有所升高, 先重启服务, 后续定位。

后续定位

考虑到最新的服务变更, 以及上线后约一周才出现的问题。

所以在服务重启后, 持续观察服务的指标情况, 发现服务实例的网络包传输量和 cpu 占用逐步增长, 网络包传输情况如下:

​

根据 cpu 和网络包的同时增长, 基本可以断定是后台有定时任务不断发送网络请求导致。

考虑到本次功能主要变更为:

使用「触发式缓存刷新」代替「定时的缓存刷新」功能

怀疑大概率与此功能的部分实现有问题有关。

这里使用的简单的 redis 的 pub/sub 机制, 可能启动了越来越多的 listener, 导致一直刷新, 查看对应代码, 也是做了类似的全局唯一处理。

代码片段如下:

​

既然不是, 剩下的就是复杂的业务模块, 一个一个排查不现实, 上工具。

查看 cpu 时间, py-spy 火焰图正合适, 在预上线准备环境, 得到火焰图如下:

​

明显看到是__get_onestore_addrs 函数占用了大量的 cpu 时间。顾名思义, 函数的功能即通过发出请求获取需要的地址。必然, 网络流量应该同比例增加。

(PS: onestore 可以理解为分布式存储系统, 类 DNS 解析, 其中存在 name->ip 的过程, __get_onestore_addrs 函数即实现了该部分功能。 在实例生成后, 会在后台定时刷新)

查看发现, 最新的变更中, 有一处改动, 将地址的刷新时间从原来的 240s 减少为 5s。然后, 在一处若干年前久远的函数调用中, 有如下写法:

​

在函数触发时, 每调用一次, 都会生成新的 onestore 实例, 换言之, 会在后台创建新的刷新任务。以此造成 CPU 时间挤占, 甚至超时的出现。

问题定位之后, 解决起来并不难。只要把这一行代码拿到 module 空间就可以 (最简单的单例模式)。

本着举一反三、杀一儆百、宁错杀不放过的原则, 检查了系统中类似的调用方式。为了以防万一, 统一在接口封装处, 添加了单例处理。避免上层使用不仔细, 造成相似的频繁刷新问题。例:

​

PS: 这里说一下, 起初没往这方面想的点是, onestore 作为系统的基础存储使用, 在各个功能模块中都有使用, 如果存在问题, 那不应该是刚爆出来甚至需要一周时间才能爆出来问题。

Q: 以前为什么没发现这部分问题？

A: 刷新时间从 240s 减少到 5s, 相当于刷新频率提升了 50 倍左右, 现在一周能爆出来的问题, 换算一下, 要服务实例发布后不间断运行一年才能爆出来问题, 考虑到日常的迭代升级, 基本不会达到临界值。

总结

问题不复杂, 甚至是老问题。定位的过程也不算曲折, 只是问题本身的复现比较耗时。可供日后借鉴的点确实不多。

如果非要说的话, 那就: CPU 问题, py-spy 你值的拥有!

时刻提醒自己

认真写代码, 写好每一行代码。

​