0%

Java jstack用法

jstack是jdk中自带的用于查看进程内线程栈的工具。当程序出现死锁时,我们可以通过jstack打印线程栈找到问题。

找出代码中的死锁

学习从一段简单的代码开始:

public class Main {
    public static void main(String[] args) {
        test1();
    }

    private static void test1() {
        final Object lock1 = new Object();
        final Object lock2 = new Object();
        Thread thread=new Thread(new Runnable() {
            public void run() {
                synchronized (lock1) {
                    try {
                        for(int i=0;i<20;i++) {
                            Thread.sleep(1000);
                            System.out.println(Thread.currentThread().getName()+" "+i);
                        }
                        synchronized (lock2) {
                            for(int i=20;i<40;i++) {
                                Thread.sleep(1000);
                                System.out.println(Thread.currentThread().getName()+" "+i);
                            }
                        }
                    } catch (InterruptedException e) {
                        e.printStackTrace();
                    }
                }
            }
        });
        thread.start();
        synchronized (lock2) {
            try {
                for(int i=0;i<20;i++) {
                    Thread.sleep(1000);
                    System.out.println(Thread.currentThread().getName()+" "+i);
                }
                synchronized (lock1) {
                    for(int i=20;i<40;i++) {
                        Thread.sleep(1000);
                        System.out.println(Thread.currentThread().getName()+" "+i);
                    }
                }

            } catch (InterruptedException e) {
                e.printStackTrace();
            }
        }
    }

}

肉眼都能看出来的死锁,程序运行20s后进入死锁状态。
首先我们先找出这个程序的进程id,建议用jps,而不是ps,原因是jps只会显示当前用户下面的java进程,等于自动帮我们过滤了。

jps -l

Main进程,id 5632,这时出动我们的主角jstack.

jstack 5632

结果如下

2017-05-23 13:57:22
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.45-b02 mixed mode):

"Attach Listener" #12 daemon prio=9 os_prio=31 tid=0x00007ff0f780c800 nid=0x4507 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Thread-0" #11 prio=5 os_prio=31 tid=0x00007ff0f80c0000 nid=0x5a03 waiting for monitor entry [0x0000700002310000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at Main$1.run(Main.java:33)
    - waiting to lock <0x000000076adb1a98> (a java.lang.Object)
    - locked <0x000000076adb1a88> (a java.lang.Object)
    at java.lang.Thread.run(Thread.java:745)

"Service Thread" #10 daemon prio=9 os_prio=31 tid=0x00007ff0f980b800 nid=0x5603 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread3" #9 daemon prio=9 os_prio=31 tid=0x00007ff0f6803000 nid=0x5403 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread2" #8 daemon prio=9 os_prio=31 tid=0x00007ff0f6802800 nid=0x5203 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" #7 daemon prio=9 os_prio=31 tid=0x00007ff0f6801800 nid=0x5003 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #6 daemon prio=9 os_prio=31 tid=0x00007ff0f90de800 nid=0x4e03 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Monitor Ctrl-Break" #5 daemon prio=5 os_prio=31 tid=0x00007ff0f90dc800 nid=0x4c03 runnable [0x0000700001bfb000]
   java.lang.Thread.State: RUNNABLE
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
    at java.net.SocketInputStream.read(SocketInputStream.java:170)
    at java.net.SocketInputStream.read(SocketInputStream.java:141)
    at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
    at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
    at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
    - locked <0x000000076af12b68> (a java.io.InputStreamReader)
    at java.io.InputStreamReader.read(InputStreamReader.java:184)
    at java.io.BufferedReader.fill(BufferedReader.java:161)
    at java.io.BufferedReader.readLine(BufferedReader.java:324)
    - locked <0x000000076af12b68> (a java.io.InputStreamReader)
    at java.io.BufferedReader.readLine(BufferedReader.java:389)
    at com.intellij.rt.execution.application.AppMainV2$1.run(AppMainV2.java:64)

"Signal Dispatcher" #4 daemon prio=9 os_prio=31 tid=0x00007ff0f8039800 nid=0x4a03 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=31 tid=0x00007ff0f9803000 nid=0x3903 in Object.wait() [0x0000700001972000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x000000076ab06f58> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
    - locked <0x000000076ab06f58> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

"Reference Handler" #2 daemon prio=10 os_prio=31 tid=0x00007ff0f9802000 nid=0x3703 in Object.wait() [0x000070000186f000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x000000076ab06998> (a java.lang.ref.Reference$Lock)
    at java.lang.Object.wait(Object.java:502)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:157)
    - locked <0x000000076ab06998> (a java.lang.ref.Reference$Lock)

"main" #1 prio=5 os_prio=31 tid=0x00007ff0f8002000 nid=0x1c03 waiting for monitor entry [0x0000700000e51000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at Main.test1(Main.java:52)
    - waiting to lock <0x000000076adb1a88> (a java.lang.Object)
    - locked <0x000000076adb1a98> (a java.lang.Object)
    at Main.main(Main.java:18)

"VM Thread" os_prio=31 tid=0x00007ff0f801f800 nid=0x3503 runnable

"GC task thread#0 (ParallelGC)" os_prio=31 tid=0x00007ff0f9003800 nid=0x2503 runnable

"GC task thread#1 (ParallelGC)" os_prio=31 tid=0x00007ff0f9004000 nid=0x2703 runnable

"GC task thread#2 (ParallelGC)" os_prio=31 tid=0x00007ff0f7801000 nid=0x2903 runnable

"GC task thread#3 (ParallelGC)" os_prio=31 tid=0x00007ff0f600e800 nid=0x2b03 runnable

"GC task thread#4 (ParallelGC)" os_prio=31 tid=0x00007ff0f600f000 nid=0x2d03 runnable

"GC task thread#5 (ParallelGC)" os_prio=31 tid=0x00007ff0f6010000 nid=0x2f03 runnable

"GC task thread#6 (ParallelGC)" os_prio=31 tid=0x00007ff0f6010800 nid=0x3103 runnable

"GC task thread#7 (ParallelGC)" os_prio=31 tid=0x00007ff0f6011000 nid=0x3303 runnable

"VM Periodic Task Thread" os_prio=31 tid=0x00007ff0f980c000 nid=0x5803 waiting on condition

JNI global references: 26


Found one Java-level deadlock:
=============================
"Thread-0":
  waiting to lock monitor 0x00007ff0f8024f38 (object 0x000000076adb1a98, a java.lang.Object),
  which is held by "main"
"main":
  waiting to lock monitor 0x00007ff0f8023bf8 (object 0x000000076adb1a88, a java.lang.Object),
  which is held by "Thread-0"

Java stack information for the threads listed above:
===================================================
"Thread-0":
    at Main$1.run(Main.java:33)
    - waiting to lock <0x000000076adb1a98> (a java.lang.Object)
    - locked <0x000000076adb1a88> (a java.lang.Object)
    at java.lang.Thread.run(Thread.java:745)
"main":
    at Main.test1(Main.java:52)
    - waiting to lock <0x000000076adb1a88> (a java.lang.Object)
    - locked <0x000000076adb1a98> (a java.lang.Object)
    at Main.main(Main.java:18)

Found 1 deadlock.

jstack直接帮我们找出来了deadlock。真实场景下,如果代码比较复杂,可能需要我们自己分析找出死锁。
如果我们自己分析,该怎么找出死锁呢?重点分析java.lang.Thread.State: BLOCKED的进程,找到
waiting to lock,看看这个锁的持有者,是不是也被锁着,沿着这个链路找下去,是不是死锁就能找出来 了。比如上面的例子中,main线程持有0x000000076adb1a98锁,等待0x000000076adb1a88锁释放,而Thread-0持有0x000000076adb1a88锁,等待0x000000076adb1a98锁释放,两个线程互相等待,而进入死锁状态。

找出CPU消耗多的代码

如果程序cpu占用很高,我们需要找到问题优化,可以配合top命令,找出最耗cpu的进程,从而找到相应代码解决问题。

  1. 先用jps找出程序pid,这里是23034

  2. 用top命令找出该进程最耗cpu的线程。下面的top是linux中的,mac里的不一样。

    top -Hp 23034
    

    结果如下图

    23046线程占了93.8的cpu,就是它.

  3. 将23046转成16进制。因为top里的pid是10进制,而jstack里是16进制,叫nid。
    可以用printf命令转换

    printf "%x\n" 23046
    

    得到5a06

  4. jstack出场

    jstack 23034 | grep 5a06
    

    结果如下:

    writeFileThread占用了最多的cpu资源。找到后,可以优化代码了.