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

转自: https://mp.weixin.qq.com/s/GUFvhOtJMg4tAdMVDWI8bA

 

原创 有趣的bug 代码中那些有趣的bug 今天

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

 

故事背景

      某天, 有开发人员找到 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 对它进行了优化, 最终在后面的日志中看不到那个异常栈. 为了看到那个异常栈, 要跑到最开始出错的时间点去查看日志.