JDK tools之jps和jstack診斷Java程序

時間 2019-12-14

標籤 jdk tools jps jstack 診斷 java 程序欄目 Java 简体版

原文原文鏈接

大部分Java開發者可能知道有這麼個工具，可是沒怎麼用過，每次還得百度一下。我也是之一 -_-!!。java

每次遇到👇下面的問題，頭是否是有點大：c++

OutOfMemoryError
程序忽然卡頓死鎖
內存泄露

我的感受jps、jstack、jmap、visualVM、jConsole、MAT都是解決這些問題的利器，今天先介紹jps、jstack。git

一、jps，先man一下看看jps是幹什麼的

NAME
       jps - Java Virtual Machine Process Status Tool
DESCRIPTION
       The  jps  tool  lists  the  instrumented  HotSpot Java Virtual Machines (JVMs) on the target system. The tool is limited to reporting  information on JVMs for which it has the access permissions.

從名字就大概知道jps是查看Java進程信息的工具，跟LInux/Unix下的ps(process status)相似，只是jps只針對Java程序。數據庫

使用語法以下：

SYNOPSIS
       jps [options] [hostid]

主要參數：

-q 不輸出類名、Jar名和傳入main方法的參數
-m 輸出傳入main方法的參數
-l 輸出main類或Jar的全限名
-v 輸出傳入JVM的參數

例如：

➜  ~ jps -m -l
2281 /Users/xxxxxx/Applications/data-integration-7.0/launcher/pentaho-application-launcher-7.0.0.0-25.jar -lib ./../libswt/osx64/ 
2312 sun.tools.jps.Jps -m -l
➜  ~

包括jps在內一共有兩個Java進程，第一列是pid,也是後面咱們要用到的信息。緩存

固然上面的信息還能夠用ps命令來查詢ps -ef或ps aux,前者Linux下的標準語法，後者是BSD風格的語法。同樣能夠查到第二列的pid。網絡

➜  ~ ps -ef | grep java
  501  2281  2261   0 11:48PM ttys000    0:52.81 /Library/Java/JavaVirtualMachines/jdk1.8.0_144.jdk/Contents/Home/bin/java -XstartOnFirstThread -Xms1024m -Xmx2048m -XX:MaxPermSize=256m -Dhttps.protocols=TLSv1,TLSv1.1,TLSv1.2 -Djava.library.path=./../libswt/osx64/ -DKETTLE_HOME= -DKETTLE_REPOSITORY= -DKETTLE_USER= -DKETTLE_PASSWORD= -DKETTLE_PLUGIN_PACKAGES= -DKETTLE_LOG_SIZE_LIMIT= -DKETTLE_JNDI_ROOT= -jar /Users/xxxxxx/Applications/data-integration-7.0/launcher/pentaho-application-launcher-7.0.0.0-25.jar -lib ./../libswt/osx64/ 
  501  2361  2285   0 11:51PM ttys001    0:00.00 grep --color=auto --exclude-dir=.bzr --exclude-dir=CVS --exclude-dir=.git --exclude-dir=.hg --exclude-dir=.svn java
➜  ~

二、jstack

NAME
       jstack - stack trace
DESCRIPTION
       jstack  prints  Java  stack  traces  of  Java threads for a given Java process or core file or a remote debug server. 
For each Java frame, the full class name, method name, 'bci' (byte code index) and line number, if available, are printed. 
With  the  -m  option,jstack  prints both Java and native frames of all threads along with the 'pc' (program counter). 
For each native frame, the closest native symbol to 'pc', if available, is printed. C++ mangled names are not demangled. 
To demangle C++ names,  the  output  of  this command may be piped to c++filt.

說白了jstack就是查看當前Java程序內線程詳細堆棧信息的工具。多線程

使用語法以下：

SYNOPSIS
       jstack [ option ] pid
       jstack [ option ] executable core
       jstack [ option ] [server-id@]remote-hostname-or-IP

主要參數：

Options:
    -F  to force a thread dump. Use when jstack <pid> does not respond (process is hung)(強制線程轉儲，此時線程會被掛起)
    -m  to print both java and native frames (mixed mode)（打印Java和native接口的堆棧信息）
    -l  long listing. Prints additional information about locks（打印關於鎖的詳細信息，若是有線程死鎖可使用jstack -l pid查看鎖或資源的持有信息）
    -h or -help to print this help message

爲了配合實戰，寫了一個會發生死鎖的多線程程序代碼以下：app

public class MyThread extends Thread {
    private Object object1;
    private Object object2;

    public MyThread(Object object1, Object object2, String threadName) {
        this.object1 = object1;
        this.object2 = object2;
        setName(threadName);
    }

    @Override
    public void run() {
        String name = Thread.currentThread().getName();
        System.out.println(name + " acquiring lock on " + object1);
        synchronized (object1) {
            System.out.println(name + " acquired lock on " + object1);
            sleep();
            System.out.println(name + " acquiring lock on " + object2);
            synchronized (object2) {
                System.out.println(name + " acquired lock on " + object2);
                sleep();
            }
            System.out.println(name + " released lock on " + object2);
        }
        System.out.println(name + " released lock on " + object2);
        System.out.println(name + " finished execution.");
    }

    private void sleep() {
        try {
            Thread.sleep(1000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

main方法以下：ide

public class MainTest {
    public static void main(String[] args) {
        Object object1 = new Object();
        Object object2 = new Object();
        Object object3 = new Object();
        MyThread myThread1 = new MyThread(object1, object2, "myThread1");
        MyThread myThread2 = new MyThread(object2, object3, "myThread2");
        MyThread myThread3 = new MyThread(object3, object1, "myThread3");

        myThread1.start();
        myThread2.start();
        myThread3.start();
    }
}

運行程序後輸出以下:svn

[root@localhost MutipleThreadTest]# java MainTest
myThread1 acquiring lock on java.lang.Object@796523ab
myThread3 acquiring lock on java.lang.Object@4335236e
myThread2 acquiring lock on java.lang.Object@5f08edd0
myThread3 acquired lock on java.lang.Object@4335236e
myThread1 acquired lock on java.lang.Object@796523ab
myThread2 acquired lock on java.lang.Object@5f08edd0
myThread3 acquiring lock on java.lang.Object@796523ab
myThread2 acquiring lock on java.lang.Object@4335236e
myThread1 acquiring lock on java.lang.Object@5f08edd0

從上面信息可知myThread一、myThread二、myThread3三個線程分別拿到一把鎖，而後等待其餘線程持有的鎖。
因爲沒有任何一個線程釋放鎖因而整個程序進入死鎖的狀態。
現場的生產狀況每每會更復雜，須要藉助工具定位分析發生死鎖的位置和緣由，下面上jstack分析一下當前的堆棧信息。
上面的介紹已經知道若是有線程死鎖可使用`jstack -l pid`查看鎖或資源的持有信息

[root@localhost ~]# jstack -l 3661
2018-01-09 17:24:15
Full thread dump Java HotSpot(TM) 64-Bit Server VM (24.79-b02 mixed mode):

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

   Locked ownable synchronizers:
    - None

"DestroyJavaVM" prio=10 tid=0x00007f03d4008800 nid=0xe4e waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"myThread3" prio=10 tid=0x00007f03d40b5800 nid=0xe5e waiting for monitor entry [0x00007f03d05f4000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at MyThread.run(MyThread.java:26)
    - waiting to lock <0x00000000d784b978> (a java.lang.Object)
    - locked <0x00000000d784b998> (a java.lang.Object)

   Locked ownable synchronizers:
    - None

"myThread2" prio=10 tid=0x00007f03d40b4000 nid=0xe5d waiting for monitor entry [0x00007f03d06f5000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at MyThread.run(MyThread.java:26)
    - waiting to lock <0x00000000d784b998> (a java.lang.Object)
    - locked <0x00000000d784b988> (a java.lang.Object)

   Locked ownable synchronizers:
    - None

"myThread1" prio=10 tid=0x00007f03d40b1800 nid=0xe5c waiting for monitor entry [0x00007f03d07f6000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at MyThread.run(MyThread.java:26)
    - waiting to lock <0x00000000d784b988> (a java.lang.Object)
    - locked <0x00000000d784b978> (a java.lang.Object)

   Locked ownable synchronizers:
    - None

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

   Locked ownable synchronizers:
    - None

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

   Locked ownable synchronizers:
    - None

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

   Locked ownable synchronizers:
    - None

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

   Locked ownable synchronizers:
    - None

"Finalizer" daemon prio=10 tid=0x00007f03d406f000 nid=0xe55 in Object.wait() [0x00007f03d0dfc000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000000d7804858> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)
    - locked <0x00000000d7804858> (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)

   Locked ownable synchronizers:
    - None

"Reference Handler" daemon prio=10 tid=0x00007f03d406d000 nid=0xe54 in Object.wait() [0x00007f03d0efd000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000000d7804470> (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 <0x00000000d7804470> (a java.lang.ref.Reference$Lock)

   Locked ownable synchronizers:
    - None

"VM Thread" prio=10 tid=0x00007f03d4068800 nid=0xe53 runnable 

"GC task thread#0 (ParallelGC)" prio=10 tid=0x00007f03d401e000 nid=0xe4f runnable 

"GC task thread#1 (ParallelGC)" prio=10 tid=0x00007f03d4020000 nid=0xe50 runnable 

"GC task thread#2 (ParallelGC)" prio=10 tid=0x00007f03d4022000 nid=0xe51 runnable 

"GC task thread#3 (ParallelGC)" prio=10 tid=0x00007f03d4024000 nid=0xe52 runnable 

"VM Periodic Task Thread" prio=10 tid=0x00007f03d40a2000 nid=0xe5b waiting on condition 

JNI global references: 114


Found one Java-level deadlock:
=============================
"myThread3":
  waiting to lock monitor 0x00007f03ac0062c8 (object 0x00000000d784b978, a java.lang.Object),
  which is held by "myThread1"
"myThread1":
  waiting to lock monitor 0x00007f0388002258 (object 0x00000000d784b988, a java.lang.Object),
  which is held by "myThread2"
"myThread2":
  waiting to lock monitor 0x00007f03ac004e28 (object 0x00000000d784b998, a java.lang.Object),
  which is held by "myThread3"

Java stack information for the threads listed above:
===================================================
"myThread3":
    at MyThread.run(MyThread.java:26)
    - waiting to lock <0x00000000d784b978> (a java.lang.Object)
    - locked <0x00000000d784b998> (a java.lang.Object)
"myThread1":
    at MyThread.run(MyThread.java:26)
    - waiting to lock <0x00000000d784b988> (a java.lang.Object)
    - locked <0x00000000d784b978> (a java.lang.Object)
"myThread2":
    at MyThread.run(MyThread.java:26)
    - waiting to lock <0x00000000d784b998> (a java.lang.Object)
    - locked <0x00000000d784b988> (a java.lang.Object)

Found 1 deadlock.

簡單分析以下：

以上結果末尾可知jstack已經檢測到了死鎖。
"myThread3"在等待"myThread1"釋放資源、"myThread1"在等待"myThread2"釋放資源、"myThread2"在等待"myThread3"釋放資源。簡單說就是資源循環依賴了致使了死鎖。
現實的狀況每每不會發生結構如此簡單的死鎖，不少狀況都是等待網絡IO、數據讀寫等耗時操做，致使線程佔用的資源不能釋放，從而致使程序假死、卡頓等狀況。
好比以前遇到過的一個場景saiku每次刷新緩存的時候都要卡好久，最後經過jstack發現每次刷緩存都會去拿olap數據庫鏈接，而且加鎖了。必須等刷緩存的相關操做執行完才能恢復，這其中就包含執行一系列的select COUNT(*)操做，而剛好存在這比樣的大表4千萬多萬行數據，一個select COUNT(*)要執行90多秒，這就悲劇了，所有刷完須要8分鐘左右系統才能恢復

堆棧中一些常見值解析

線程狀態（java.lang.Thread.State）

NEW：至今還沒有啓動的線程的狀態。
RUNNABLE：可運行線程的線程狀態。處於可運行狀態的某一線程正在 Java 虛擬機中運行，但它可能正在等待操做系統中的其餘資源，好比處理器。
BLOCKED：受阻塞而且正在等待monitor lock的某一線程的線程狀態。處於受阻塞狀態的某一線程正在等待monitor lock，以便進入一個同步的塊/方法，或者在調用 Object.wait 以後再次進入同步的塊/方法。好比等待執行synchronized代碼塊或者使用synchronized標記的方法。
WAITING：某一等待線程的線程狀態。某一線程由於調用下列方法之一而處於等待狀態。
- 不帶超時值的 Object.wait
- 不帶超時值的 Thread.join
- LockSupport.park 處於等待狀態的線程正等待另外一個線程，以執行特定操做。例如，已經在某一對象上調用了 Object.wait() 的線程正等待另外一個線程，以便在該對象上調用 Object.notify() 或 Object.notifyAll()。已經調用了 Thread.join() 的線程正在等待指定線程終止。
TIMED_WAITING：具備指定等待時間的某一等待線程的線程狀態。某一線程由於調用如下帶有指定正等待時間的方法之一而處於定時等待狀態：

Thread.sleep
帶有超時值的 Object.wait
帶有超時值的 Thread.join
LockSupport.parkNanos
LockSupport.parkUntil

TERMINATED：已終止線程的線程狀態。線程已經結束執行。

各類線程ID

prio：線程的優先級;
tid：java Thread id;
nid:native線程的id, 很是關鍵，後面再使用jstack時補充；

使用top -Hp pid查看進程的線程狀態時線程的id就對應這裏的nid,在堆棧中nid是使用16進製表示的所以可使用以下工具作簡單的轉換

printf "%x\n" 21742

實戰一下，找當前我的博客系統中最運行時間最長的線程

首先找到博客進程id

$ ps -ef | grep java

結果爲：

zhangsan   27952     1  4  2017 ?        1-07:19:12 java -Xms128m -Xmx128m -Dfile.encoding=UTF-8 -jar tale-least.jar

查看當前線程信息

$ top -Hp 27952

top - 23:32:06 up 59 days, 10:06,  2 users,  load average: 0.06, 0.04, 0.01
Tasks:  16 total,   1 running,  15 sleeping,   0 stopped,   0 zombie
Cpu(s):  5.7%us,  3.0%sy,  0.0%ni, 91.3%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   1019988k total,   907552k used,   112436k free,   151028k buffers
Swap:        0k total,        0k used,        0k free,   387324k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                       
27965 zhangsan    20   0 2116m 213m  13m R  7.3 21.4   1727:05 java                                                           
27954 zhangsan    20   0 2116m 213m  13m S  0.7 21.4 133:27.59 java                                                           
27952 zhangsan    20   0 2116m 213m  13m S  0.0 21.4   0:00.00 java                                                           
27953 zhangsan    20   0 2116m 213m  13m S  0.0 21.4   0:00.22 java                                                           
27955 zhangsan    20   0 2116m 213m  13m S  0.0 21.4   0:00.06 java                                                           
27956 zhangsan    20   0 2116m 213m  13m S  0.0 21.4   0:00.55 java                                                           
27957 zhangsan    20   0 2116m 213m  13m S  0.0 21.4   0:00.00 java                                                           
27958 zhangsan    20   0 2116m 213m  13m S  0.0 21.4   0:28.53 java                                                           
27959 zhangsan    20   0 2116m 213m  13m S  0.0 21.4   0:09.86 java                                                           
27960 zhangsan    20   0 2116m 213m  13m S  0.0 21.4   0:00.00 java                                                           
27961 zhangsan    20   0 2116m 213m  13m S  0.0 21.4  13:00.98 java                                                           
27962 zhangsan    20   0 2116m 213m  13m S  0.0 21.4   0:00.57 java                                                           
27969 zhangsan    20   0 2116m 213m  13m S  0.0 21.4   2:04.10 java                                                           
27970 zhangsan    20   0 2116m 213m  13m S  0.0 21.4   0:49.48 java                                                           
27971 zhangsan    20   0 2116m 213m  13m S  0.0 21.4   2:16.69 java                                                           
18940 zhangsan    20   0 2116m 213m  13m S  0.0 21.4   0:00.00 java

發現線程pid 27954運行時間最長，轉換成16進制

$ printf "%x\n" 27954
6d32

使用jstack該線程的堆棧信息

$ jstack 27952 | grep 6d32 | grep -v grep
"VM Thread" os_prio=0 tid=0x00007fc6ec094000 nid=0x6d32 runnable

發現是Java VM相關的線程怪不得運行時間最長，這裏根據實際狀況鑑別VM系統線程和本身的業務線程

相關標籤/搜索

每日一句

每一个你不满意的现在，都有一个你没有努力的曾经。