狂打出错日志导致的 CPU 飙升

程序中输出日志, 是正常普通的事情, 可是由于对日志的输出的预估不足, 可能导致意想不到的后果. 曾经遇到过几次由于程序代码狂打日志, 导致 CPU 报警的情况. 今天就聊曾经遇到过的一次.

某天, 某开发人员说他们生产上有些机器 CPU 使用率不知道什么时候已经飙升到 90%以上了, 不知道怎么回事, 我心想, 这不是好事么, CPU 使用率高, 说明你们代码没让 CPU 闲着, 提高生产效率. 简单抛了几个问题给开发人员. 开发人员给了具体的回答.

之前 CPU 使用率多少? 回答: 这个 app 是做后端消息队列处理的, 基本没啥业务在这里, 都是从消息队列拿消息, 然后数据库查一下, 之后调用后端其它 web service, 所以是一个 IO 密集型的, 平时开 30 多个线程并发处理. CPU 稳定在 5% 一下.
最近有什么代码发布和更改吗? 回答: 半年内没做过发布和改动;
除了 CPU 使用率高, 有没有其它症状? 回答: CPU 使用率高之后, 处理变慢, 没见到其它症状;
你们有没有怀疑的对象? 回答: 如果我们有其它怀疑对象, 就不来找你们帮忙了. 从开发人员给的描述里面看, 基本没啥可以具体怀疑的地方. 进一步观察该应用的各个指标, 只有 CPU 使用率比较异常, 其它没有啥异常的地方.

一般 CPU 高, 要从线程看起, 做了几个 thread dump, 大概推断出问题的所在, 进一步分析, 验证了这个推断.

从 thread dump 看到好几个线程都是在 blocked 状态, 它们都是在等 java.io.PrintStream 某个 instance 的一把锁, 这个锁正是 PrintStream 的 println 方法里面的.

为什么会调用这个 println 方法呢? 原来这些 thread 都遇到了一个 CommonException, 程序捕获这个 CommonException 之后, 就在 catch 块里面调用了 CommonException 的 printStacktrace() 方法; 然而这个方法对于没有指定要 print 到哪里去的情况, 默认是输出到 System.err, 这个 System.err 正是一个 PrintStream.
其实看到这里感觉也没啥问题, 很多人都是把 log 输出到 System.out, System.err 的. 这个应用里面, System.out, System.err 都是重定向到 log 文件的, 也就是和 log4j 一样, 都输出到了文件系统. 他们的文件都叫 stdout.log. 仔细查看输出的问题, 就会发现, 输出文件的效率真是太高了. 每秒 2 个文件, 每个 6M:

随便打开一个文件来看, 里面基本全是出错的 stacktrace, 每个 stacktrace 大概只有 10 行, 6M 的 log 文件里面大概有 3500 个线程的 stacktrace. 这意味着每秒有大概 7000 次写入. 由于一个线程不可能连续写入这种 stacktrace, 所以每秒有 7000 次的锁获取 /释放发生在 System.err, 也就是上面的 PrintStream 的同步锁上面. 由于这个锁是一个高频率使用, 并且必然会发生竞争的锁, 所以不可能有偏向锁, 自旋锁存在, 必然膨胀到最重量的锁.

那么这样问题就可以解释了: 30 个线程不停的在出错, 不停的要写日志到 System.err 中, 这里有个锁, 它们要频繁的获取 /释放, 它们从获取到释放的时间又超短, 仅仅写一个 10 行日志. 本来获取释放锁操作就是一个比较重量的操作, 这个重量就是指的 CPU 消耗比较高. 频繁短期的获取释放锁必然会导致 CPU 飙升.

原文链接: http://www.tianxiaohui.com/index.php/Java%E7%9B%B8%E5%85%B3/%E7%8B%82%E6%89%93%E5%87%BA%E9%94%99%E6%97%A5%E5%BF%97%E5%AF%BC%E8%87%B4%E7%9A%84-CPU-%E9%A3%99%E5%8D%87.html