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

谁吃掉了 Java 异常的代码栈?

  •  
  •   manecocomph · 2021-02-03 12:27:18 +08:00 · 3263 次点击
    这是一个创建于 1150 天前的主题,其中的信息可能已经有所发展或是发生改变。
    转自: https://mp.weixin.qq.com/s/GUFvhOtJMg4tAdMVDWI8bA

    通常情况下, 如果我们遇到某些异常, 都把出错异常栈打出来, 这样方便查看到底哪行代码出错了, 是怎么一层层调用到了这行代码. 可是有时候, 虽然我们明确写了打印出错异常栈, 可是偏偏日志里面却没有出错栈, 这是怎么一回事呢?



    故事背景

    某天, 有开发人员找到 SRE 说, 他们的代码出了一个新的空指针错误, 可是日志里面却没有出错栈, 想让 SRE 帮忙确定一下, 到底是日志丢了, 还是代码哪里出了问题.

    SRE 查看了源代码, 代码确实是打印完整出错栈, 可是日志却没有相关信息. 于是 SRE 想使用 BTrace 暴力注入, 查看到底怎么回事. 可是事与愿违, 这些出错的机器, 由于未知的原因, SRE 的账号登录不了. 所以只能通过其它方式去解决这个谜题.



    代码模拟

    为了较为直观的展示这个问题, 考虑下面这段代码, 它最后打印出来的结果会是什么样子?



    package com.tianxiaohui.art;



    public class StackEater {



    public static void main(String[] args) {

    StackEater.makeException();

    }



    public static void makeException() {

    //循环 N 次, 只为每次都发生空指针异常

    for (int i = 0; i < 1000000000; i++) {

    try {

    Object obj = createObject();

    System.out.println(obj.hashCode());

    } catch (Exception e) {//打印出错栈

    e.printStackTrace();

    }

    }

    }



    public static Object createObject() {

    returnnull;//为了创造空指针异常, 返回一个空对象,

    }

    }



    最开始的时候, 事情还是在我们预料之中:

    图片




    可是随着循环次数增加, 最后打印的结果, 变成了这个样子:

    java.lang.NullPointerException

    java.lang.NullPointerException

    java.lang.NullPointerException



    谜题答案

    在讲出答案之前, 我们先复习一下 JIT 优化的一些细节: 当某些 Java 方法或者某些循环体里面的代码, 在某个滑动时间窗口之内执行的次数足够多, 足够 hot 的时候, JIT 就出手把他们编译成机器代码了. 编译的机器代码根据优化层度不同, 又分为几个等级. 代码越热, 优化层度越高.

    另外, 在 Java 运行过程中, 如果出错产生异常, 一般都是把异常栈信息封装在 Throwable 或其子类中. 采集当前线程的异常栈对于 JVM 来说, 是一个相对耗时的操作, 需要额外耗费比较多的 CPU cycle.

    针对 JDK 自带的一些异常类, 如果 JIT 做代码编译的时候, 会有更贴心的优化策略: 出于性能考虑, 把出错栈信息省略掉, 只保留异常类的类名. 同时, 提供了一个 JVM flag: -XX:+OmitStackTraceInFastThrow 来选择打开, 还是关闭这个贴心优化. 默认是打开的.

    所以, 我们的故事当中, 就是因为那个 JDK 自带异常出错的频率太高, 导致 JIT 对它进行了优化, 最终在后面的日志中看不到那个异常栈. 为了看到那个异常栈, 要跑到最开始出错的时间点去查看日志.
    23 条回复    2021-02-05 09:53:11 +08:00
    340244120w
        1
    340244120w  
       2021-02-03 12:41:19 +08:00   ❤️ 2
    居然最后没有公众号链接!
    不过说回来,我们为了减少异常栈输出,自定义业务类异常类都是
    @Override
    public Throwable fillInStackTrace() {
    return null;
    }
    sadfQED2
        2
    sadfQED2  
       2021-02-03 12:48:48 +08:00 via Android   ❤️ 1
    这就是我不敢去写 java 的原因,jvm 各种奇奇怪怪的优化太多了。这特么谁能想到啊
    tedzhou1221
        3
    tedzhou1221  
       2021-02-03 13:07:51 +08:00 via iPhone   ❤️ 1
    类似情况,在我们生产有发生过。

    公共方法,空指针。 一堆报错日志发到运维邮箱。内容就一行 就显示空指针,也没显示哪一行出问题……
    manecocomph
        4
    manecocomph  
    OP
       2021-02-03 13:29:44 +08:00
    @340244120w 哈哈, 原文里面有, 最后就不放了. 谢谢捧场. 你这个返回 null 的我还是第一次见. 涨见识.
    manecocomph
        5
    manecocomph  
    OP
       2021-02-03 13:30:16 +08:00
    @sadfQED2 JIT 编译时会有各种优化. 大多数不会产生这种异常.
    manecocomph
        6
    manecocomph  
    OP
       2021-02-03 13:31:23 +08:00
    @tedzhou1221 那基本就是这个问题. 所以要找到最初报这个空指针的地方. 或者使用 BTrace 检测 new NPEException 的点, 打印 stack.
    cheng6563
        7
    cheng6563  
       2021-02-03 14:06:30 +08:00
    这种一般找到第一个异常就行了。
    manecocomph
        8
    manecocomph  
    OP
       2021-02-03 14:10:30 +08:00
    @cheng6563 是的. 如果第一个异常太久了或者日志被 rotate 了 第一个日志就比较难找.
    timi
        9
    timi  
       2021-02-03 14:44:26 +08:00
    如果日志滚没了,有办法让 JVM 逆优化回去吗
    manecocomph
        10
    manecocomph  
    OP
       2021-02-03 14:55:41 +08:00
    @timi 一段时间内这个方法或者 for 循环体内的方法不再过热. 它是计算一个滑动时间窗口内被执行的次数. 如果次数降下来 因为存编译代码的空间有限, 这段代码可能会被逆优化.

    当然, 如果重启 server, 自然又恢复到开始状态了.
    justlikemaki
        11
    justlikemaki  
       2021-02-03 14:55:49 +08:00   ❤️ 1
    线上遇到过这种问题,xx 同事说,加了个日志修复了。其实是,重启了就恢复了。
    manecocomph
        12
    manecocomph  
    OP
       2021-02-03 16:09:51 +08:00
    @justlikemaki 哈哈, 那是不是过段时间又重现了. xx 同事在去掉日志又可以修复一次...
    xuanbg
        13
    xuanbg  
       2021-02-04 04:27:15 +08:00
    @timi 不需要滚回去,重启就有了
    uselessVisitor
        14
    uselessVisitor  
       2021-02-04 08:49:16 +08:00
    排版难受
    hustmisa
        15
    hustmisa  
       2021-02-04 10:04:59 +08:00
    这不是很正常且符合逻辑的优化么

    如果相同的异常堆栈特别多,类似你这种循环 100000,异常的堆栈会增加 io 甚至写满磁盘,这时候你重启或者找到错误开始的位置就能看到堆栈,而且一个完全重复无数次的东西记录干嘛,你业务日志会记录完全重复没用的东西么;
    如果相同的错误很少,根本不会被省略。
    manecocomph
        16
    manecocomph  
    OP
       2021-02-04 12:36:37 +08:00
    @hustmisa 是正常且符合逻辑的优化. 只是很少看到这种文档介绍这种知识, 导致第一次见到这种情形, 不知道栈去哪里了.
    manecocomph
        17
    manecocomph  
    OP
       2021-02-04 12:37:26 +08:00
    @beichenhpy 是的, 我为了省事, 直接复制过来了. 直接读微信原文排版会好点. 下次写个提示.
    MineDog
        18
    MineDog  
       2021-02-04 17:01:48 +08:00
    @340244120w #1 构造方法可以直接关闭,为什么要重写呢?
    340244120w
        19
    340244120w  
       2021-02-04 17:51:28 +08:00 via iPhone
    @MineDog

    一个是防止其他人滥用 e.printstacktrace 。

    一个是性能问题,填充栈特别吃性能,而且还是加锁的方法。很多人诟病用异常代替业务里的 if 判断影响性能,就是这个原因。
    340244120w
        20
    340244120w  
       2021-02-04 17:52:56 +08:00 via iPhone
    @MineDog 重写更简单,构造方法也挺好,主要当时也没注意到
    MineDog
        21
    MineDog  
       2021-02-04 17:57:12 +08:00
    @340244120w #20 参数控制的方式更灵活吧
    340244120w
        22
    340244120w  
       2021-02-04 18:06:54 +08:00
    @MineDog #21 嗯嗯
    hustmisa
        23
    hustmisa  
       2021-02-05 09:53:11 +08:00
    @manecocomph 嗯嗯确实是,这个优化的很隐蔽。。
    关于   ·   帮助文档   ·   博客   ·   API   ·   FAQ   ·   我们的愿景   ·   实用小工具   ·   3435 人在线   最高记录 6543   ·     Select Language
    创意工作者们的社区
    World is powered by solitude
    VERSION: 3.9.8.5 · 26ms · UTC 10:35 · PVG 18:35 · LAX 03:35 · JFK 06:35
    Developed with CodeLauncher
    ♥ Do have faith in what you're doing.