转载

你真的会看异常堆栈信息么

​    接口在线上服务器出现异常的时候,我们第一时间就是去服务器看下log,检查log是否有异常堆栈信息,如果有异常堆栈信息的话,再结合api的access log,是非常容易找出问题所在的,所以我们要学会看异常堆栈信息。异常堆栈信息如何看呢?下面我们一起来看一下。

下面是一个简单的demo:

package person.ismallboy.console;
​
import java.io.IOException;
​
public class TestEx {
    private void fun1() throws IOException {
        throw new IOException("level 1 exception");
    }
​
    private void fun2() throws IOException {
        try {
            fun1();
            System.out.println("2");
        } catch (IOException e) {
            throw new IOException("level 2 exception", e);
        }
    }
​
    private void fun3() {
        try {
            fun2();
            System.out.println("3");
        } catch (IOException e) {
            throw new RuntimeException("level 3 exception", e);
        }
    }
​
    public static void main(String[] args) {
        try {
            new TestEx().fun3();
            System.out.println("0");
        } catch (Exception e) {
            e.printStackTrace();
        }
    }
}

执行上面demo的main函数,输出结果如下:

Connected to the target VM, address: '127.0.0.1:57353', transport: 'socket'
java.lang.RuntimeException: level 3 exception
  at person.ismallboy.console.TestEx.fun3(TestEx.java:24)
  at person.ismallboy.console.TestEx.main(TestEx.java:30)
Caused by: java.io.IOException: level 2 exception
  at person.ismallboy.console.TestEx.fun2(TestEx.java:15)
  at person.ismallboy.console.TestEx.fun3(TestEx.java:21)
  ... 1 more
Caused by: java.io.IOException: level 1 exception
  at person.ismallboy.console.TestEx.fun1(TestEx.java:7)
  at person.ismallboy.console.TestEx.fun2(TestEx.java:12)
  ... 2 more
Disconnected from the target VM, address: '127.0.0.1:57353', transport: 'socket'

既然是堆栈,那肯定是FILO(先进后出)的,了解过线程堆栈(比如函数调用的时候参数和局部变量的入栈和出栈)的同学应该比较清楚。所以我们看打出来的异常堆栈的顺序,也应该是从下往上看,就是从第12行开始往上看,一直看到第2行,发现第10行才是问题的根源,异常是一层一层地往外抛出,直至抛出到最外层(即没有catch为止)。第2行的RuntimeException只是真正异常的一个外层表现而已,异常的根源还是要看堆栈最底部的信息。本demo异常抛出的流程大概如下:

你真的会看异常堆栈信息么

所以,Caused by(中文是“由...造成的”意思)也就比较好理解了,就是这个异常时由哪里触发的意思。fun3的异常是由fun2的异常触发的,而fun2的异常又是由fun1的异常触发的。

解决了异常堆栈查看顺序的问题,我们细看上面demo打印出来的异常堆栈信息,会发现,打印出来的堆栈信息不完整,比如第8行的“ ... 1 more”和第12行的“ ... 2 more”,为什么jvm会省略部分堆栈信息呢?下面我们继续探讨一下。

1.为什么有些堆栈信息被隐藏了?... 2 more

我们来看一下打印异常堆栈信息的远吗,输出函数是

java.lang.Throwable#printEnclosedStackTrace

输出异常堆栈函数源代码如下:

/**
     * Print our stack trace as an enclosed exception for the specified
     * stack trace.
     */
    private void printEnclosedStackTrace(PrintStreamOrWriter s,
                                         StackTraceElement[] enclosingTrace,
                                         String caption,
                                         String prefix,
                                         Set<Throwable> dejaVu) {
        assert Thread.holdsLock(s.lock());
        if (dejaVu.contains(this)) {
            s.println("/t[CIRCULAR REFERENCE:" + this + "]");
        } else {
            dejaVu.add(this);
            // Compute number of frames in common between this and enclosing trace
            StackTraceElement[] trace = getOurStackTrace();
            int m = trace.length - 1;
            int n = enclosingTrace.length - 1;
            while (m >= 0 && n >=0 && trace[m].equals(enclosingTrace[n])) {
                m--; n--;
            }
            int framesInCommon = trace.length - 1 - m;
​
            // Print our stack trace
            s.println(prefix + caption + this);
            for (int i = 0; i <= m; i++)
                s.println(prefix + "/tat " + trace[i]);
            if (framesInCommon != 0)
                s.println(prefix + "/t... " + framesInCommon + " more");
​
            // Print suppressed exceptions, if any
            for (Throwable se : getSuppressed())
                se.printEnclosedStackTrace(s, trace, SUPPRESSED_CAPTION,
                                           prefix +"/t", dejaVu);
​
            // Print cause, if any
            Throwable ourCause = getCause();
            if (ourCause != null)
                ourCause.printEnclosedStackTrace(s, trace, CAUSE_CAPTION, prefix, dejaVu);
        }
    }

我们来分析一下这个函数,这里其实是一个回调输出堆栈的过程。我们先来说一下为什么会隐藏部分堆栈,当然是为了提高性能,省略一些不必要的输出啦,输出的内容越多,io耗时越慢嘛。

其实“... n more”的部分是重复的堆栈部分。我们分析一下上面这个函数“printEnclosedStackTrace”,翻译为“打印封闭堆栈跟踪信息”,“封闭”暂且可以理解为“完整的”,这个函数有两个比较重要的变量,分别是“enclosingTrace”和“trace ”,这两个参数是什么关系呢?其实可以简单理解为“enclosingTrace”是“trace ”的父级堆栈,函数printEnclosedStackTrace中的while循环,就是为倒序找出“enclosingTrace”和“trace ”中从哪一个栈帧开始就不一样了,即“enclosingTrace”和“trace ”是有一部分是一样的(从数组后面倒回来),就是为了算出有多少个栈帧信息是重复可以隐藏的,相同的栈帧就不用重复输出啦。下图就是第12行“ ... 2 more”隐藏的栈帧信息:

你真的会看异常堆栈信息么

按照上面的堆栈输出,第12行“ ... 2 more”隐藏2行堆栈信息,其实就是第7和第8行的栈帧信息;然后第8行“ ... 1 more”隐藏的1个堆栈信息,其实就是第4行的那个栈帧。这样应该好理解了吧,每个异常都输出一个完整的堆栈信息的话,都是从main函数开始,到当前的函数的所有函数调用的栈帧信息,里面函数的调用栈帧信息都会包括外层的函数调用栈帧信息,所以都输出的话,很多都是重复的,为了提高效率,减少io以及输出的内容太多又杂乱,所以jvm以“... n more”的方式隐藏了重复的部分。

当然,如果想不隐藏,可以重写 java .lang .Throwable #printEnclosedStackTrace,去掉while部分,就可以看到每个异常的完整堆栈信息了,可以参考https://blog.csdn.net/michaelehome/article/details/79484722来验证。

参考:

https://www.jianshu.com/p/9f902c5517f8

https://blog.csdn.net/michaelehome/article/details/79484722

欢迎关注微信公众号“ismallboy”,请扫码并关注以下公众号,并在公众号下面回复“堆栈”,获得本文最新内容。

你真的会看异常堆栈信息么

原文  http://www.cnblogs.com/ismallboy/p/12779200.html
正文到此结束
Loading...