1. 程式人生 > >你真的會看異常堆疊資訊麼

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

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

                                                           

&n