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++;
}
}
}
通过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
可以看到此时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)
...
仍旧是运行在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();
}
}
通过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.
可以看到,最后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();
。