Java之jstack工具的使用

jstack是什么

jstack是一个可以看到一个java进程内各个线程的堆栈信息，本文将介绍在我们的程序中怎么使用jstack命令查找导致JVM占用CPU过高的code以及JVM运行停滞（死锁）的code。由于在生产环境，我们的代码肯定是跑在服务器上，一般来说都不会有类似IDE里运行java main方法的图形化界面，因此这里使用javac和java命令模拟在服务器上跑程序的情况。

a. JVM占用CPU过高

代码准备

首先，准备一份运行会导致JVM CPU使用率过高的代码，通过jstack分析代码慢在哪处。代码准备：

public class SlowCode {
    public static void main(String[] args) {
        int i = 0;
        while (true) {
            i++;
        }
    }
}
1
2
3
4
5
6
7
8

通过javac命令：javac SlowCode.java编译成java字节码文件，再运行字节码文件:java SlowCode。

jstack使用

1. 通过top命令找到对应的java进程

top

在本例子中，这个java进程的ID是510。

2. 继续通过top命令找到该进程下的线程占用资源情况

top -Hp 510

我这里占用CPU最高的线程ID是511，对应的十六进制数为0x1ff.因为jstack里记录的线程ID是16进制，所以这里先做一个转换。

3. 通过jstack命令查看该进程里的线程堆栈信息

jstack 510指定的是java进程ID

[root@od-v6-52-8330e35-rsync-server-6558cb47f8-7gz96 /]# jstack 510
2022-10-30 11:50:11
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.221-b11 mixed mode):

"Attach Listener" #8 daemon prio=9 os_prio=0 tid=0x00007fe798001000 nid=0x319 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Service Thread" #7 daemon prio=9 os_prio=0 tid=0x00007fe7c00c2000 nid=0x208 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007fe7c00b7800 nid=0x207 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007fe7c00b4800 nid=0x206 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

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

"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007fe7c0080000 nid=0x204 in Object.wait() [0x00007fe7c420b000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000000ec208ed8> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
	- locked <0x00000000ec208ed8> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)

"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007fe7c007d800 nid=0x203 in Object.wait() [0x00007fe7c430c000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000000ec206c00> (a java.lang.ref.Reference$Lock)
	at java.lang.Object.wait(Object.java:502)
	at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
	- locked <0x00000000ec206c00> (a java.lang.ref.Reference$Lock)
	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

"main" #1 prio=5 os_prio=0 tid=0x00007fe7c0009800 nid=0x1ff runnable [0x00007fe7c8c02000]
   java.lang.Thread.State: RUNNABLE
	at SlowCode.main(SlowCode.java:5)

"VM Thread" os_prio=0 tid=0x00007fe7c0073800 nid=0x202 runnable 

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007fe7c001e800 nid=0x200 runnable 

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007fe7c0020800 nid=0x201 runnable 

"VM Periodic Task Thread" os_prio=0 tid=0x00007fe7c00c5000 nid=0x209 waiting on condition 

JNI global references: 5
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50

可以看到此时511线程正运行在SlowCode.java第5行。

4. 过几分钟之后再运行jstack命令，查看当前线程运行在哪

[root@od-v6-52-8330e35-rsync-server-6558cb47f8-7gz96 /]# jstack 510
2022-10-30 11:57:36
...
"main" #1 prio=5 os_prio=0 tid=0x00007fe7c0009800 nid=0x1ff runnable [0x00007fe7c8c02000]
   java.lang.Thread.State: RUNNABLE
	at SlowCode.main(SlowCode.java:5)
...	
1
2
3
4
5
6
7

仍旧是运行在SlowCode.java第5行。因此可以基本断定是第5行code：i++;导致CPU使用率增加。

b. JVM运行停滞（死锁）

代码准备

首先，准备一份存在死锁的代码，这份代码的表现形式是：JVM的CPU使用率不高，但是程序迟迟没有结束。代码准备：

import java.util.concurrent.locks.Lock;
import java.util.concurrent.locks.ReentrantLock;

public class DeadLock {
    public static void main(String[] args) {
        Lock lockA = new ReentrantLock();
        Lock lockB = new ReentrantLock();
        Thread thread1 = new Thread(new Runnable() {
            @Override
            public void run() {
                lockA.lock();
                try {
                    Thread.sleep(1000);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
                lockB.lock();
                while (true) {

                }
            }
        });
        Thread thread2 = new Thread(new Runnable() {
            @Override
            public void run() {
                lockB.lock();
                try {
                    Thread.sleep(1000);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
                lockA.lock();
                while (true) {

                }
            }
        });
        thread1.start();
        thread2.start();
    }
}

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42

通过javac命令：javac DeadLock.java编译成java字节码文件，再运行字节码文件:java DeadLock。

jstack使用

1. 通过top命令找到对应的java进程

top

我这里这个java进程的ID是1689。可以看到，这个进程的CPU使用率并不高。

2. 通过jstack命令查看该进程里的线程堆栈信息

jstack 1689指定的是java进程ID

[root@od-v6-52-8330e35-rsync-server-6558cb47f8-7gz96 /]# jstack 1689
2022-10-30 12:20:09
...
Found one Java-level deadlock:
=============================
"Thread-1":
  waiting for ownable synchronizer 0x00000000ec25c918, (a java.util.concurrent.locks.ReentrantLock$NonfairSync),
  which is held by "Thread-0"
"Thread-0":
  waiting for ownable synchronizer 0x00000000ec25c948, (a java.util.concurrent.locks.ReentrantLock$NonfairSync),
  which is held by "Thread-1"

Java stack information for the threads listed above:
===================================================
"Thread-1":
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000000ec25c918> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
	at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
	at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
	at DeadLock$2.run(DeadLock.java:32)
	at java.lang.Thread.run(Thread.java:748)
"Thread-0":
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000000ec25c948> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
	at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
	at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
	at DeadLock$1.run(DeadLock.java:17)
	at java.lang.Thread.run(Thread.java:748)

Found 1 deadlock.
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38

可以看到，最后jstack的提示是发现1个死锁：Thread-1在等待锁0x00000000ec25c918，当前被Thread-0占有；Thread-0在等待锁0x00000000ec25c948，当前被Thread-1占有。同时，指出Thread-0当前运行在DeadLock.java第17行:lockB.lock();，Thread-1当前运行在DeadLock.java第32行:lockA.lock();。