Java Trouble Shooting - 使用線程棧

時間 2020-01-13

標籤 java trouble shooting 使用線程欄目 Java 简体版

原文原文鏈接

什麼是線程棧(thread dump)

線程棧是某個時間點，JVM全部線程的活動狀態的一個彙總；經過線程棧，能夠查看某個時間點，各個線程正在作什麼，一般使用線程棧來定位軟件運行時的各類問題，例如 CPU 使用率特別高，或者是響應很慢，性能大幅度下滑。
線程棧包含了多個線程的活動信息，一個線程的活動信息一般看起來以下所示：java

"main" prio=10 tid=0x00007faac0008800 nid=0x9f0 waiting on condition [0x00007faac6068000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
        at java.lang.Thread.sleep(Native Method)
        at ThreadDump.main(ThreadDump.java:4)

這條線程的線程棧信息包含了如下這些信息：linux

線程的名字：其中 main 就是線程的名字，須要注意的是，當使用 Thread 類來建立一條線程，而且沒有指定線程的名字時，這條線程的命名規則爲 Thread-i，i 表明數字。若是使用 ThreadFactory 來建立線程，則線程的命名規則爲 pool-i-thread-j，i 和 j 分別表明數字。
線程的優先級：prio=10 表明線程的優先級爲 10
線程 id：tid=0x00007faac0008800 表明線程 id 爲 0x00007faac0008800，而 nid=0x9f0 表明該線程對應的操做系統級別的線程 id。所謂的 nid，換種說法就是 native id。在操做系統中，分爲內核級線程和用戶級線程，JVM 的線程是用戶態線程，內核不知情，但每一條 JVM 的線程都會映射到操做系統一條具體的線程
線程的狀態：java.lang.Thread.State: TIMED_WAITING (sleeping) 以及 waiting on condition 表明線程當前的狀態
線程佔用的內存地址：[0x00007faac6068000] 表明當前線程佔用的內存地址
線程的調用棧：at java.lang.Thread.sleep(Native Method)* 以及它以後的相相似的信息，表明線程的調用棧

回顧線程狀態

NEW：線程初建立，未運行
RUNNABLE：線程正在運行，但不必定消耗 CPU
BLOCKED：線程正在等待另一個線程釋放鎖
WAITING：線程執行了 wait, join, park 方法
TIMED_WAITING：線程調用了sleep, wait, join, park 方法，與 WAITING 狀態不一樣的是，這些方法帶有表示時間的參數。

例如如下代碼：算法

public static void main(String[] args) throws InterruptedException {
        int sum = 0;
        while (true) {
            int i = 0;
            int j = 1;
            sum = i + j;
        }
}

main 線程對應的線程棧就是數據庫

"main" prio=10 tid=0x00007fe1b4008800 nid=0x1292 runnable [0x00007fe1bd88f000]
   java.lang.Thread.State: RUNNABLE
        at ThreadDump.main(ThreadDump.java:7)

其狀態爲 RUNNABLE微信

若是是如下代碼，兩個線程會競爭同一個鎖，其中只有一個線程能得到鎖，而後進行 sleep(time)，從而進入 TIMED_WAITING 狀態，另一個線程因爲等待鎖，會進入 BLOCKED 狀態。ide

public static void main(String[] args) throws InterruptedException {

        Thread t1 = new Thread(new Runnable() {

            @Override
            public void run() {
                try {
                    fun1();
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
            }
        });
        
        t1.setDaemon(false);
        t1.setName("MyThread1");
        
        Thread t2 = new Thread(new Runnable() {
            
            @Override
            public void run() {
                try {
                    fun2();
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
            }
        });
        
        t2.setDaemon(false);
        t2.setName("MyThread2");
        t1.start();
        t2.start();
        */
        
    }

    private static synchronized void fun1() throws InterruptedException {
        System.out.println("t1 acquire");
        Thread.sleep(Integer.MAX_VALUE);
    }

    private static synchronized void fun2() throws InterruptedException {
        System.out.println("t2 acquire");
        Thread.sleep(Integer.MAX_VALUE);
    }

對應的線程棧爲：工具

"MyThread2" prio=10 tid=0x00007ff1e40b1000 nid=0x12eb waiting for monitor entry [0x00007ff1e07f6000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at ThreadDump.fun2(ThreadDump.java:45)
        - waiting to lock <0x00000000eb8602f8> (a java.lang.Class for ThreadDump)
        at ThreadDump.access$100(ThreadDump.java:1)
        at ThreadDump$2.run(ThreadDump.java:25)
        at java.lang.Thread.run(Thread.java:745)

"MyThread1" prio=10 tid=0x00007ff1e40af000 nid=0x12ea waiting on condition [0x00007ff1e08f7000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
        at java.lang.Thread.sleep(Native Method)
        at ThreadDump.fun1(ThreadDump.java:41)
        - locked <0x00000000eb8602f8> (a java.lang.Class for ThreadDump)
        at ThreadDump.access$000(ThreadDump.java:1)
        at ThreadDump$1.run(ThreadDump.java:10)
        at java.lang.Thread.run(Thread.java:745)

能夠看到，t1 線程的調用棧裏有這麼一句 - locked <0x00000000eb8602f8> (a java.lang.Class for ThreadDump)，說明它得到了鎖，而且進行 sleep(sometime) 操做，所以狀態爲 TIMED_WAITING。而 t2 線程因爲獲取不到鎖，因此在它的調用棧裏能看到 - waiting to lock <0x00000000eb8602f8> (a java.lang.Class for ThreadDump)，說明它正在等待鎖，所以進入 BLOCKED 狀態。性能

對於 WAITING 狀態的線程棧，可使用如下代碼來模擬製造：ui

private static final Object lock = new Object();
    public static void main(String[] args) throws InterruptedException {
        synchronized (lock) {
            lock.wait();
        }
    }

獲得的線程棧爲：this

"main" prio=10 tid=0x00007f1fdc008800 nid=0x13fe in Object.wait() [0x00007f1fe1fec000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000000eb860640> (a java.lang.Object)
        at java.lang.Object.wait(Object.java:503)
        at ThreadDump.main(ThreadDump.java:7)
        - locked <0x00000000eb860640> (a java.lang.Object)

如何輸出線程棧

因爲線程棧反映的是 JVM 在某個時間點的線程狀態，所以分析線程棧時，爲避免偶然性，有必要多輸出幾份進行分析。如下以 HOT SPOT JVM 爲例，首先能夠經過如下兩種方式獲得 JVM 的進程 ID。

jps 命令

[root@localhost ~]# jps
5163 ThreadDump
5173 Jps

ps -ef | grep java

[root@localhost ~]# ps -ef | grep java
root       5163   2479  0 01:18 pts/0    00:00:00 java ThreadDump
root       5185   2553  0 01:18 pts/1    00:00:00 grep --color=auto java

接下來經過 JDK 自帶的 jstack 命令

[root@localhost ~]# jstack 5163
2017-04-21 01:19:41
Full thread dump Java HotSpot(TM) 64-Bit Server VM (24.79-b02 mixed mode):

"Attach Listener" daemon prio=10 tid=0x00007f72b8001000 nid=0x144c waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Service Thread" daemon prio=10 tid=0x00007f72d4095000 nid=0x1433 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" daemon prio=10 tid=0x00007f72d4092800 nid=0x1432 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" daemon prio=10 tid=0x00007f72d4090000 nid=0x1431 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x00007f72d408e000 nid=0x1430 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=10 tid=0x00007f72d4065000 nid=0x142f in Object.wait() [0x00007f72d9b83000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000000eb804858> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)
        - locked <0x00000000eb804858> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:151)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

"Reference Handler" daemon prio=10 tid=0x00007f72d4063000 nid=0x142e in Object.wait() [0x00007f72d9c84000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000000eb804470> (a java.lang.ref.Reference$Lock)
        at java.lang.Object.wait(Object.java:503)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)
        - locked <0x00000000eb804470> (a java.lang.ref.Reference$Lock)

"main" prio=10 tid=0x00007f72d4008800 nid=0x142c in Object.wait() [0x00007f72dc971000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000000eb860620> (a java.lang.Object)
        at java.lang.Object.wait(Object.java:503)
        at ThreadDump.main(ThreadDump.java:7)
        - locked <0x00000000eb860620> (a java.lang.Object)

"VM Thread" prio=10 tid=0x00007f72d405e800 nid=0x142d runnable 

"VM Periodic Task Thread" prio=10 tid=0x00007f72d40a0000 nid=0x1434 waiting on condition 

JNI global references: 107

便可將線程棧輸出到控制檯。若輸出信息過多，在控制檯上不方便分析，則能夠將輸出信息重定向到文件中，以下所示：

jstack 5163 > thread.stack

若系統中沒有 jstack 命令，由於 jstack 命令是 JDK 帶的，而有的環境只安裝了 JRE 環境。則能夠用 kill -3 命令來代替，kill -3 pid。Java虛擬機提供了線程轉儲(Thread dump)的後門，經過這個後門，能夠將線程堆棧打印出來。這個後門就是經過向Java進程發送一個QUIT信號， Java虛擬機收到該信號以後，將系
統當前的JAVA線程調用堆棧打印出來。

如果有運行圖形界面的環境，也可使用一些圖形化的工具，例如 JVisualVM 來生成線程棧文件。

使用線程棧定位問題

發現死鎖

當兩個或多個線程正在等待被對方佔有的鎖，死鎖就會發生。死鎖會致使兩個線程沒法繼續運行，被永遠掛起。
如下代碼會產生死鎖

/**
 *
 *
 * @author beanlam
 * @version 1.0
 *
 */
public class ThreadDump {
    
    public static void main(String[] args) throws InterruptedException {
        Object lock1 = new Object();
        Object lock2 = new Object();
        
        new Thread1(lock1, lock2).start();
        new Thread2(lock1, lock2).start();
    }

    private static class Thread1 extends Thread {
        Object lock1 = null;
        Object lock2 = null;
        
        public Thread1(Object lock1, Object lock2) {
            this.lock1 = lock1;
            this.lock2 = lock2;
            this.setName(getClass().getSimpleName());
        }
        
        public void run() {
            synchronized (lock1) {
                try {
                    Thread.sleep(2);
                } catch(Exception e) {
                    e.printStackTrace();
                }
                
                synchronized (lock2) {
                    
                }
            }
        }
    }
    
    private static class Thread2 extends Thread {
        Object lock1 = null;
        Object lock2 = null;
        
        public Thread2(Object lock1, Object lock2) {
            this.lock1 = lock1;
            this.lock2 = lock2;
            this.setName(getClass().getSimpleName());
        }
        
        public void run() {
            synchronized (lock2) {
                try {
                    Thread.sleep(2);
                } catch(Exception e) {
                    e.printStackTrace();
                }
                
                synchronized (lock1) {
                    
                }
            }
        }
    }
}

對應的線程棧是

"Thread2" prio=10 tid=0x00007f9bf40a1000 nid=0x1472 waiting for monitor entry [0x00007f9bf8944000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at ThreadDump$Thread2.run(ThreadDump.java:63)
        - waiting to lock <0x00000000eb860498> (a java.lang.Object)
        - locked <0x00000000eb8604a8> (a java.lang.Object)

"Thread1" prio=10 tid=0x00007f9bf409f000 nid=0x1471 waiting for monitor entry [0x00007f9bf8a45000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at ThreadDump$Thread1.run(ThreadDump.java:38)
        - waiting to lock <0x00000000eb8604a8> (a java.lang.Object)
        - locked <0x00000000eb860498> (a java.lang.Object)

Found one Java-level deadlock:
=============================
"Thread2":
  waiting to lock monitor 0x00007f9be4004f88 (object 0x00000000eb860498, a java.lang.Object),
  which is held by "Thread1"
"Thread1":
  waiting to lock monitor 0x00007f9be40062c8 (object 0x00000000eb8604a8, a java.lang.Object),
  which is held by "Thread2"

Java stack information for the threads listed above:
===================================================
"Thread2":
        at ThreadDump$Thread2.run(ThreadDump.java:63)
        - waiting to lock <0x00000000eb860498> (a java.lang.Object)
        - locked <0x00000000eb8604a8> (a java.lang.Object)
"Thread1":
        at ThreadDump$Thread1.run(ThreadDump.java:38)
        - waiting to lock <0x00000000eb8604a8> (a java.lang.Object)
        - locked <0x00000000eb860498> (a java.lang.Object)

Found 1 deadlock.

能夠看到，當發生了死鎖的時候，堆棧中直接打印出了死鎖的信息 Found one Java-level deadlock: ，並給出了分析信息。

要避免死鎖的問題，惟一的辦法是修改代碼。死鎖可能會致使整個系統的癱瘓，具體的嚴重程度取決於這些線程執行的是什麼性質的功能代碼，要想恢復系統，臨時也是惟一的規避辦法是將系統重啓。

定位 CPU 太高的緣由

首先須要藉助操做系統提供的一些工具，來定位消耗 CPU 太高的 native 線程。不一樣的操做系統，提供的不一樣的 CPU 統計命令以下所示：

操做系統	solaris	linux	aix
命令名稱	prstat -L <pid>	top -p <pid>	ps -emo THREAD

以 Linux 爲例，首先經過 top -p <pid> 輸出該進程的信息，而後輸入 H，查看全部的線程的統計狀況。

top - 02:04:54 up  2:43,  3 users,  load average: 0.10, 0.05, 0.05
Threads:  13 total,   0 running,  13 sleeping,   0 stopped,   0 zombie
%Cpu(s):  97.74 us,  0.2 sy,  0.0 ni, 2.22 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem:   1003456 total,   722012 used,   281444 free,        0 buffers
KiB Swap:  2097148 total,    62872 used,  2034276 free.    68880 cached Mem

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
3368 zmw2 25 0 256m 9620 6460 R 93.3 0.7 5:42.06 java
3369 zmw2 15 0 256m 9620 6460 S 0.0 0.7 0:00.00 java
3370 zmw2 15 0 256m 9620 6460 S 0.0 0.7 0:00.00 java
3371 zmw2 15 0 256m 9620 6460 S 0.0 0.7 0:00.00 java
3372 zmw2 15 0 256m 9620 6460 S 0.0 0.7 0:00.00 java
3373 zmw2 15 0 256m 9620 6460 S 0.0 0.7 0:00.00 java
3374 zmw2 15 0 256m 9620 6460 S 0.0 0.7 0:00.00 java
3375 zmw2 15 0 256m 9620 6460 S 0.0 0.7 0:00.00 java

這個命令輸出的 PID 表明的是 native 線程的 id，如上所示，id 爲 3368 的 native 線程消耗 CPU 最高。在Java Thread Dump文件中，每一個線程都有tid=...nid=...的屬性，其中nid就是native thread id，只不過nid中用16進制來表示。例如上面的例子中3368的十六進制表示爲0xd28.在Java線程中查找nid=0xd28便是本地線程對應Java線程。

"main" prio=1 tid=0x0805c988 nid=0xd28 runnable [0xfff65000..0xfff659c8]
at java.lang.String.indexOf(String.java:1352)
at java.io.PrintStream.write(PrintStream.java:460)
- locked <0xc8bf87d8> (a java.io.PrintStream)
at java.io.PrintStream.print(PrintStream.java:602)
at MyTest.fun2(MyTest.java:16)
- locked <0xc8c1a098> (a java.lang.Object)
at MyTest.fun1(MyTest.java:8)
- locked <0xc8c1a090> (a java.lang.Object)
at MyTest.main(MyTest.java:26)

致使 CPU 太高的緣由有如下幾種緣由：

Java 代碼死循環
Java 代碼使用了複雜的算法，或者頻繁調用
JVM 自身的代碼致使 CPU 很高

若是在Java線程堆棧中找到了對應的線程ID,而且該Java線程正在執行Native code,說明致使CPU太高的問題代碼在JNI調用中，此時須要打印出 Native 線程的線程棧，在 linux 下，使用 pstack <pid> 命令。
若是在 native 線程堆棧中能夠找到對應的消耗 CPU 太高的線程 id，能夠直接定位爲 native 代碼的問題。
可是有可能在 native 線程堆棧中找不到對應的消耗 CPU 太高的線程 id，這多是由於 JNI 調用中從新建立的線程來執行，那麼在 Java 線程堆棧中就不存在該線程的信息，也有多是虛擬機自身代碼致使的 CPU 太高，如堆內存使用太高致使的頻繁 FULL GC ，或者 JVM 的 Bug。

定位性能降低緣由

性能降低通常是因爲資源不足所致使。若是資源不足，那麼有大量的線程在等待資源，打印的線程堆棧若是發現大量的線程停在一樣的調用上下文上，那麼就說明該系統資源是瓶頸。
致使資源不足的緣由可能有：

資源數量配置太少（如鏈接池鏈接配置過少等），而系統當前的壓力比較大，資源不足致使了某些線程不能及時得到資源而等待在那裏(即掛起)
得到資源的線程把持資源時間過久，致使資源不足，例如如下代碼：

void fun1() {
   Connection conn = ConnectionPool.getConnection();//獲取一個數據庫鏈接
   //使用該數據庫鏈接訪問數據庫
   //數據庫返回結果，訪問完成
   //作其它耗時操做,但這些耗時操做數據庫訪問無關，
   conn.close(); //釋放鏈接回池
}

設計不合理致使資源佔用時間太久，如SQL語句設計不恰當，或者沒有索引致使的數據庫訪問太慢等。
資源用完後，在某種異常狀況下，沒有關閉或者回池，致使可用資源泄漏或者減小，從而致使資源競爭。

定位系統假死緣由

致使系統掛死的緣由有不少，其中有一個最多見的緣由是線程掛死。每次打印線程堆棧，該線程必然都在同一個調用上下文上，所以定位該類型的問題原理是，經過打印屢次堆棧，找出對應業務邏輯使用的線程，經過對比先後打印的堆棧確認該線程執行的代碼段是否一直沒有執行完成。經過打印屢次堆棧，找到掛起的線程（即不退出）。
致使線程沒法退出的緣由可能有：