记一次Linux server偶发CPU飙升问题的跟进与解决

背景进入6月后 , 随着一个主要功能版本api的上线 , 服务端的QPS翻了一倍 , 平时服务器的CPU使用稳定在30%上下 , 高峰期则在60%上下 , 但是偶尔会有单台机器出现持续数分钟突然飙到90%以上 , 导致大量api响应缓慢超过客户端等待时间 , 触发其主动断开连接产生大量Nginx499 。
问题分析与解决问题期间器资源情况仔细查看问题期间的zabbix监控数据 , 发现90%的CPU占用中有10%上下是sys time, 5%上下是softirq time , 两者相加可占到接近20%, interrupt和context switch数由之前的10k/s飙升至20k+/s 。
定位kafka log发送代码首先猜测就是某个新加功能实现有bug , 可能造成长时间未执行完成 , 多个类似请求长期占用CPU而后又被切换为其他线程 , 反复在这些耗时请求中来回切换却没法完成任意一个请求 , 并造成后续请求在队列中排队等待 , 导致大量请求超时响应 。直接入手分析定位新增的某个复杂功能接口 , 确认不存在死循环的可能 , 怀疑是接口太耗性能长期占用CPU导致后续请求来不及处理最终连锁反应导致雪崩 。
仔细分析其实现 , 发现总共会触发30+次kafka log发送 , 之前一直认为使用异步批量发送kafka log的情况下 , 多发几次log应该不会存在什么问题 , 不过这里一个请求触发30+次 kafka log发送确实有点太多了 。
本着怀疑的精神决定实际验证一番kafka log发送耗时 , 结果发现每次kafka调用耗时居然在0.2-2ms之间波动 , 这相当于该复杂接口功能请求光是发送kafka消息就需要6-60ms时间 , 与之前认为应该很快的假设不符!
进一步分析原因 , 发现原来沿用的kafka producer初始化配置有大坑 , 其设置了batch_size=20之前一直理解为是每20条log触发一次实际发送 , 结果起始batch_size的单位是字节 , 其表示的是每满20字节触发一次实际发送==!所以实际效果是每次kafka log send都会触发实际发送 。通过修改batch_size为64k并设置linger_ms为500ms , 验证kafka log一边为批量发送模式后 , 再次测试kafka消息单次调用耗时变为了<0.1ms 。
修改线上api服务kafka参数 , 并将复杂接口kafka send操作从30+次优化为10+次 , reload服务后 , 意外发现内存占用居然还降了50%(2G=>1G) , 但是对于日常interrupt、context switch次数未观察到明显下降 。
修改后连续几天未再出现CPU飙升偶发问题 , 但是坚持不到一周再次有机器出现类似问题 , 优化前平均1~2天一次 , 多的时候一天就有两三次 , 优化后出现频率降低为一周两三次 , 从这个角度来看优化具有一定效果 。
尝试扩容解决由于刚上了一个大版本功能 , 客户端确实新增了很多api调用 , 随着新版本覆盖用户数逐步升高 , 单机负载逐步升高 , 于是考虑再扩个容看能否解决问题 , 在某天下午快速扩容一台机器后 , 晚上又出现了该问题 , 该简单方案宣告失败 。
定位linux内存水位在前两个方案尝试解决问题失败后 , 开始细究一下每5分钟打印一次的机器top快照 , 仔细硬瞅之下还真发现点端倪:查看了单台机器过去近10次CPU飙涨时段的指标 , 发现free内存一般在CPU飙涨前剩余不到200M , 而CPU恢复正常后free内存一般都剩余>1G , 这个看上去有点不同寻常 。进一步按图索骥观察到
kswapd_low_wmark_hit_quickly取值每天增长上千次 , 直觉上感觉是偏高的 。
难道问题是free内存不足、回收引起的?然而zabbix监控上显示的可用内存一直都是>5G , 理论上不应该存在不足才对 , 进一步探究了解到了free内存回收与内存水位的概念 。
内存水位作用【记一次Linux server偶发CPU飙升问题的跟进与解决】Linux的设计思路是尽量多的使用空闲内存 , 除了保留一定量的真正空闲立马可用的内存作为free内存保证系统正常运转外 , 其他空闲内存会尽量用于系统缓存(buffer+cache) , 当free内存不足时则从buffer、cache中回收为free内存即可 , 而一般我们说linux的可用内存都是指available内存 , 其实际包括free+可回收的buffer+cache内存 , 这也是zabbix监控中可用内存使用的指标 。


推荐阅读