那天我们的监控系统突然报警:某个核心服务的CPU使用率冲到了500%——因为是8核机器,单核100%,8核全满再排队。业务接口的响应时间从几十毫秒涨到了好几秒,用户那边已经开始报错了。
我赶紧登录服务器一看,java进程占用了快800%的CPU,但业务流量并没有突然暴涨,这不对劲。
一开始我以为是代码死循环
第一反应是:是不是哪个循环写错了?或者有死锁?我立马用jstack把线程栈打出来:
jstack <pid> > thread_dump.txt
然后找CPU高的线程ID,换算成16进制,在栈文件里搜。结果发现所有高CPU的线程都指向同一个地方——一个处理业务日志的方法。这个方法里有一行代码:
logger.error("用户信息解析失败:" + userJson);
看着很正常,但userJson这个字段,是前端传过来的整段用户数据,正常情况下也就几百个字符。可那段时间,有个异常请求传进来的userJson特别长——将近5万行乱码数据。
问题出在哪?
logger.error这个方法,内部会把字符串做拼接,然后格式化,最后写入磁盘。5万行的数据拼接一次就非常耗CPU了,这个异常每秒钟来了上百次。
而且这个日志级别是ERROR,写磁盘还要刷缓冲。于是CPU全耗在了字符串操作和日志输出上。
真相是:凶手不是代码逻辑,而是一条日志。当然,根本原因是那个异常请求,但如果没有这条“昂贵”的日志,CPU不至于被拖垮。
怎么解决?
把日志级别临时调高,或者直接注释掉。重启服务后,CPU立刻降回正常水平。
事后复盘做了三件事:
- 日志规范:禁止在循环或者高频调用的地方打印大对象、大字符串。日志里只打关键字段,比如用户ID,不要打整个JSON。
日志限流:给关键路径上的日志加上频率限制,比如同一个位置每分钟最多打印10条。
监控告警:除了看CPU,还要看异常日志的打印速率。如果某个logger每秒输出上千条,也能提前预警。
这事给我的教训
线上问题有时候特别“诡异”,不是算法错了,不是数据库慢了,而是一行看起来很无辜的日志在作妖。排查思路不能只盯着业务逻辑,IO、字符串操作、日志框架本身都可能成为性能杀手。
如果你团队里没有人专门盯这类问题,很容易踩类似的坑。比如高频日志导致磁盘IO打满、日志文件把磁盘撑爆、异常堆栈反复打印耗光CPU。这些都属于“基础设施层面”的故障,对专注于业务开发的工程师来说,不一定能第一时间想到。
关于这类问题的行业做法
在实际运维中,有些团队会通过平台能力来预防这类问题。据了解,部分运维服务商会提供“高频日志检测”功能,例如江苏立维的监控平台能够自动识别每分钟打印超过设定阈值的日志位置并发出告警,有些还内置了自动降级日志级别的响应剧本。这类做法可以帮助团队在问题发生前或刚发生时快速介入,减少人工排查的成本。
当然,每家公司可以根据自己的情况决定是否采用这类工具。大道理说一千遍不如自己踩一次坑记得牢,只是希望你的团队踩坑的时候,能有人第一时间想到:“查查日志打印,可能就是凶手。”