V2EX = way to explore
V2EX 是一个关于分享和探索的地方
现在注册
已注册用户请  登录
manecocomph
V2EX  ›  Java

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

  •  
  •   manecocomph · 2019-06-23 23:48:50 +08:00 · 3352 次点击
    这是一个创建于 1959 天前的主题,其中的信息可能已经有所发展或是发生改变。

    程序中输出日志, 是正常普通的事情, 可是由于对日志的输出的预估不足, 可能导致意想不到的后果. 曾经遇到过几次由于程序代码狂打日志, 导致 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

    2 条回复    2019-06-24 08:11:44 +08:00
    jaskle
        1
    jaskle  
       2019-06-24 08:04:14 +08:00 via Android
    日志最好是无锁队列进行消费,当然也存在问题比如突然断电或程序崩掉导致后面的未记录,当然这是 c 系当心的问题。Java 是不会崩掉的,除非内存炸了,当然,这样最后几条也没意义
    petelin
        2
    petelin  
       2019-06-24 08:11:44 +08:00 via iPhone
    很有意义多谢 一楼是最佳实践 几乎所有 metric 上传 都应该放在 channel 里慢慢搞
    关于   ·   帮助文档   ·   博客   ·   API   ·   FAQ   ·   实用小工具   ·   971 人在线   最高记录 6679   ·     Select Language
    创意工作者们的社区
    World is powered by solitude
    VERSION: 3.9.8.5 · 25ms · UTC 20:25 · PVG 04:25 · LAX 13:25 · JFK 16:25
    Developed with CodeLauncher
    ♥ Do have faith in what you're doing.