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

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

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

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