你真的會看異常堆疊資訊麼

ismallboy發表於2020-04-26

​    介面線上上伺服器出現異常的時候，我們第一時間就是去伺服器看下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”，請掃碼並關注以下公眾號，並在公眾號下面回覆“堆疊”，獲得本文最新內容。

                                                          　

 

相關文章