JVM命令之jstack深入讲解-原创手记-慕课网

在JVM命令使用演示这篇文章里演示了一些jvm命令的使用，这篇文章重点对jstack做一些深入的讲解。

作用

jstack主要用于生成java虚拟机当前时刻的线程快照。线程快照是当前java虚拟机内每一条线程正在执行的方法堆栈的集合，生成线程快照的主要目的是定位线程出现长时间停顿的原因，如线程间死锁、死循环、请求外部资源导致的长时间等待等。线程出现停顿的时候通过jstack来查看各个线程的调用堆栈，就可以知道没有响应的线程到底在后台做什么事情，或者等待什么资源。如果现在运行的java程序呈现hung的状态，jstack是非常有用的。

使用

先看看看帮助

~ ᐅ jstack -help
Usage:
jstack [-l] <pid>
(to connect to running process)
jstack -F [-m] [-l] <pid>
(to connect to a hung process)
jstack [-m] [-l] <executable> <core>
(to connect to a core file)
jstack [-m] [-l] [server_id@]<remote server IP or hostname>
(to connect to a remote debug server)
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)
-l long listing. Prints additional information about locks
-h or -help to print this help message

参数解释一下

-F：当正常输出的请求不被响应时，强制输出线程堆栈。

-l：除堆栈外，会打印出额外的锁信息，在发生死锁时可以用jstack -l pid来观察锁持有情况

-m：如果调用到本地方法的话，可以显示C/C++的堆栈

示例

~ ᐅ jstack -F 86200

~ ᐅ jstack -l 86200

~ ᐅ jstack -m 86200

效果

~ ᐅ jstack -l 86200
2018-06-27 09:06:27
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.92-b14 mixed mode):
"Attach Listener" #22 daemon prio=9 os_prio=31 tid=0x00007f93b9865000 nid=0xd07 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
Locked ownable synchronizers:
- None
"DestroyJavaVM" #21 prio=5 os_prio=31 tid=0x00007f93b996b800 nid=0x1803 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
Locked ownable synchronizers:
- None
"Buiest thread" #20 prio=5 os_prio=31 tid=0x00007f93b8138800 nid=0xa203 runnable [0x0000700004903000]
java.lang.Thread.State: RUNNABLE
at com.mmall.practice.example.jvm.SearchBusiestCPU$2.run(SearchBusiestCPU.java:176)
Locked ownable synchronizers:
- None
。。。省略一部分细节。。。
"VM Thread" os_prio=31 tid=0x00007f93b9842000 nid=0x2d03 runnable
"GC task thread#0 (ParallelGC)" os_prio=31 tid=0x00007f93b980d000 nid=0x1d07 runnable
"GC task thread#1 (ParallelGC)" os_prio=31 tid=0x00007f93b980d800 nid=0x1f03 runnable
"GC task thread#2 (ParallelGC)" os_prio=31 tid=0x00007f93b980e800 nid=0x2a03 runnable
"GC task thread#3 (ParallelGC)" os_prio=31 tid=0x00007f93b980f000 nid=0x5403 runnable
"VM Periodic Task Thread" os_prio=31 tid=0x00007f93b8aea000 nid=0x3b03 waiting on condition
JNI global references: 62

分析说明

想要通过jstack来分析线程，首先要知道jstack命令查看线程堆栈信息时可能会看到的线程的状态。首先看一个Monitor的概念

Monitor是 Java中用以实现线程之间的互斥与协作的主要手段，它可以看成是对象或者 Class的锁。每一个对象都有，也仅有一个 monitor。上面这个图，描述了线程和 Monitor之间关系，以及线程的状态转换图。

进入区(Entrt Set):表示线程通过synchronized要求获取对象的锁。如果对象未被锁住,则迚入拥有者;否则则在进入区等待。一旦对象锁被其他线程释放,立即参与竞争。

拥有者(The Owner):表示某一线程成功竞争到对象锁。

等待区(Wait Set):表示线程通过对象的wait方法,释放对象的锁,并在等待区等待被唤醒。

从图中可以看出，一个 Monitor在某个时刻，只能被一个线程拥有，该线程就是 “Active Thread”，而其它线程都是 “Waiting Thread”，分别在两个队列 “ Entry Set”和 “Wait Set”里面等候。在 “Entry Set”中等待的线程状态是 “Waiting for monitor entry”，而在 “Wait Set”中等待的线程状态是 “in Object.wait()”。先看 “Entry Set”里面的线程。我们称被 synchronized保护起来的代码段为临界区。当一个线程申请进入临界区时，它就进入了 “Entry Set”队列。

jstack命令输出的堆栈信息值得关注的线程状态及说明如下：

Deadlock（重点关注），死锁线程，一般指多个线程调用间，进入相互资源占用，导致一直等待无法释放的情况。
Runnable，一般指该线程正在执行状态中，该线程占用了资源，正在处理某个请求，有可能正在传递SQL到数据库执行，有可能在对某个文件操作，有可能进行数据类型等转换。
Waiting on condition（重点关注），等待资源，或等待某个条件的发生。具体原因需结合实际堆栈来分析。
一种情况是网络非常忙，几乎消耗了所有的带宽，仍然有大量数据等待网络读写；
另一种情况也可能是网络空闲，但由于路由等问题，导致包无法正常的到达。
如果堆栈信息明确是应用代码，则证明该线程正在等待资源。一般是大量读取某资源，且该资源采用了资源锁的情况下，线程进入等待状态，等待资源的读取。
又或者，正在等待其他线程的执行等。
如果发现有大量的线程都在处在 Wait on condition，从线程 stack看，正等待网络读写，这可能是一个网络瓶颈的征兆。因为网络阻塞导致线程无法执行。
另外一种出现 Wait on condition的常见情况是该线程在 sleep，等待 sleep的时间到了时候，将被唤醒。
Waiting on monitor entry（重点关注），等待进入一个临界区
Object.wait() 或 TIMED_WAITING，说明它获得了监视器之后，又调用了 java.lang.Object.wait() 方法。每个 Monitor在某个时刻，只能被一个线程拥有，该线程就是 “Active Thread”，而其它线程都是 “Waiting Thread”，分别在两个队列 “ Entry Set”和 “Wait Set”里面等候。在 “Entry Set”中等待的线程状态是 “Waiting for monitor entry”，而在 “Wait Set”中等待的线程状态是 “in Object.wait()”。当线程获得了 Monitor，如果发现线程继续运行的条件没有满足，它则调用对象（一般就是被 synchronized 的对象）的 wait() 方法，放弃了 Monitor，进入 “Wait Set”队列。
此时线程状态大致为以下几种：
java.lang.Thread.State: TIMED_WAITING (on object monitor)；
java.lang.Thread.State: WAITING (on object monitor)；
Blocked（重点关注），线程阻塞，是指当前线程执行过程中，所需要的资源长时间等待却一直未能获取到，被容器的线程管理器标识为阻塞状态，可以理解为等待资源超时的线程

死锁案例演示

先准备一段死锁的代码

@Slf4j
public class DeadLock implements Runnable {
    public int flag = 1;
    //静态对象是类的所有对象共享的
    private static Object o1 = new Object(), o2 = new Object();

    @Override
    public void run() {
        log.info("flag:{}", flag);
        if (flag == 1) {
            synchronized (o1) {
                try {
                    Thread.sleep(500);
                } catch (Exception e) {
                    e.printStackTrace();
                }
                synchronized (o2) {
                    log.info("1");
                }
            }
        }
        if (flag == 0) {
            synchronized (o2) {
                try {
                    Thread.sleep(500);
                } catch (Exception e) {
                    e.printStackTrace();
                }
                synchronized (o1) {
                    log.info("0");
                }
            }
        }
    }

    public static void main(String[] args) {
        DeadLock td1 = new DeadLock();
        DeadLock td2 = new DeadLock();
        td1.flag = 1;
        td2.flag = 0;
        //td1,td2都处于可执行状态，但JVM线程调度先执行哪个线程是不确定的。
        //td2的run()可能在td1的run()之前运行
        new Thread(td1).start();
        new Thread(td2).start();
    }
}

运行结果如下：

14:47:19.351 [Thread-1] INFO com.mmall.concurrency.example.deadLock.DeadLock - flag:0
14:47:19.351 [Thread-0] INFO com.mmall.concurrency.example.deadLock.DeadLock - flag:1

程序输出了两行内容，就不再打印其它的东西了，但是程序并没有停止。这样就产生了死锁。

使用jstack命令看一下堆栈信息

~ ᐅ jps
93893 Launcher
94055 Jps
93894 DeadLock
34413
~ ᐅ jstack -l 93894
2018-06-28 14:48:26
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.92-b14 mixed mode):
"Attach Listener" #13 daemon prio=9 os_prio=31 tid=0x00007ff14c101800 nid=0x1307 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
Locked ownable synchronizers:
- None
"DestroyJavaVM" #12 prio=5 os_prio=31 tid=0x00007ff14c0fe000 nid=0x1703 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
Locked ownable synchronizers:
- None
"Thread-1" #11 prio=5 os_prio=31 tid=0x00007ff14ca77000 nid=0x3d03 waiting for monitor entry [0x000070000c45c000]
java.lang.Thread.State: BLOCKED (on object monitor)
at com.mmall.concurrency.example.deadLock.DeadLock.run(DeadLock.java:43)
- waiting to lock <0x000000076b5115c0> (a java.lang.Object)
- locked <0x000000076b5115d0> (a java.lang.Object)
at java.lang.Thread.run(Thread.java:745)
Locked ownable synchronizers:
- None
"Thread-0" #10 prio=5 os_prio=31 tid=0x00007ff14ca4b000 nid=0x3c03 waiting for monitor entry [0x000070000c359000]
java.lang.Thread.State: BLOCKED (on object monitor)
at com.mmall.concurrency.example.deadLock.DeadLock.run(DeadLock.java:31)
- waiting to lock <0x000000076b5115d0> (a java.lang.Object)
- locked <0x000000076b5115c0> (a java.lang.Object)
at java.lang.Thread.run(Thread.java:745)
Locked ownable synchronizers:
- None
。。。此处省略部分无用的thread堆栈信息。。。
"VM Thread" os_prio=31 tid=0x00007ff14b82b000 nid=0x2d03 runnable
"GC task thread#0 (ParallelGC)" os_prio=31 tid=0x00007ff14c012800 nid=0x2107 runnable
"GC task thread#1 (ParallelGC)" os_prio=31 tid=0x00007ff14c013000 nid=0x2003 runnable
"GC task thread#2 (ParallelGC)" os_prio=31 tid=0x00007ff14c816000 nid=0x2a03 runnable
"GC task thread#3 (ParallelGC)" os_prio=31 tid=0x00007ff14c816800 nid=0x5403 runnable
"VM Periodic Task Thread" os_prio=31 tid=0x00007ff14ca0b000 nid=0x3a03 waiting on condition
JNI global references: 42
Found one Java-level deadlock:
=============================
"Thread-1":
waiting to lock monitor 0x00007ff14b0195c8 (object 0x000000076b5115c0, a java.lang.Object),
which is held by "Thread-0"
"Thread-0":
waiting to lock monitor 0x00007ff14b0174c8 (object 0x000000076b5115d0, a java.lang.Object),
which is held by "Thread-1"

Java stack information for the threads listed above:
===================================================
"Thread-1":
at com.mmall.concurrency.example.deadLock.DeadLock.run(DeadLock.java:43)
- waiting to lock <0x000000076b5115c0> (a java.lang.Object)
- locked <0x000000076b5115d0> (a java.lang.Object)
at java.lang.Thread.run(Thread.java:745)
"Thread-0":
at com.mmall.concurrency.example.deadLock.DeadLock.run(DeadLock.java:31)
- waiting to lock <0x000000076b5115d0> (a java.lang.Object)
- locked <0x000000076b5115c0> (a java.lang.Object)
at java.lang.Thread.run(Thread.java:745)
Found 1 deadlock.

这个堆栈明显告诉我们 Found one Java-level deadlock，指出造成死锁的两个线程的内容。又通过Java stack information for the threads listed above列出更详细的死锁的信息，并指出产生死锁的代码行数及竞争的资源。

注意

1、不同的 JAVA虚机的线程 DUMP的创建方法和文件格式可能不一样，不同的 JVM版本， dump信息也有差别。

2、在实际运行中，往往一次 dump的信息，还不足以确认问题。建议产生2~3次 dump信息，如果每次 dump都指向同一个问题，才可以确定问题的典型性

欢迎关注课程《Java并发编程与高并发解决方案》、《Java开发企业级权限管理系统》