jstack是java虚拟机自带的一种堆栈跟踪工具,通过它可以定位出一些代码运行中出现的问题。
找出导致cpu飙高的代码位置
使用top命令查看cpu当前状态
top - 09:41:26 up 77 days, 23:17, 4 users, load average: 0.17, 0.12, 0.07
Tasks: 212 total, 1 running, 211 sleeping, 0 stopped, 0 zombie
%Cpu(s): 0.1 us, 0.2 sy, 0.0 ni, 99.7 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 32649012 total, 2005940 free, 16002368 used, 14640704 buff/cache
KiB Swap: 16449532 total, 16307432 free, 142100 used. 14596072 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
30207 root 20 0 12.548g 1.097g 13792 S 0.7 3.5 1:18.67 java
31017 root 20 0 12.596g 1.891g 13600 S 0.7 6.1 2:17.35 java
20 root 20 0 0 0 0 S 0.3 0.0 16:06.52 rcuos/4
4344 root 20 0 0 0 0 S 0.3 0.0 0:00.87 kworker/1:0
5585 root 20 0 11.727g 460612 13688 S 0.3 1.4 0:15.43 java
29987 root 20 0 12.550g 734016 13680 S 0.3 2.2 1:05.43 java
30430 root 20 0 12.744g 1.525g 13760 S 0.3 4.9 1:49.44 java
31493 root 20 0 12.569g 1.519g 16332 S 0.3 4.9 2:01.62 java
从以上cpu状态来看,未出现异常
然后,执行下面的代码
public void doLoop(){
new Thread(()->{
int i = 1;
while(i > 0){
System.out.println("死循环中。。。");
}
}) .start();
}
再查看cpu状态
top - 10:20:11 up 77 days, 23:55, 4 users, load average: 0.56, 0.85, 0.88
Tasks: 211 total, 1 running, 210 sleeping, 0 stopped, 0 zombie
%Cpu(s): 6.1 us, 16.3 sy, 0.0 ni, 77.5 id, 0.0 wa, 0.0 hi, 0.1 si, 0.0 st
KiB Mem : 32649012 total, 242660 free, 15986512 used, 16419840 buff/cache
KiB Swap: 16449532 total, 16028384 free, 421148 used. 14727860 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
6993 root 20 0 11.729g 436964 13676 S 100.0 1.3 0:39.36 java
5448 root 20 0 143664 5492 3944 S 13.9 0.0 2:08.24 sshd
6184 root 20 0 107932 624 532 S 8.3 0.0 1:12.85 tail
6279 root 20 0 0 0 0 S 2.6 0.0 0:17.30 kworker/0:0
21202 root 20 0 0 0 0 S 2.6 0.0 0:29.92 kworker/5:2
30810 root 20 0 0 0 0 S 2.3 0.0 0:22.66 kworker/4:3
29924 root 20 0 0 0 0 S 2.0 0.0 0:21.74 kworker/3:1
29975 root 20 0 0 0 0 S 1.7 0.0 0:18.18 kworker/2:1
可以看到有一个java的进程cpu占用超过了100%,这就是刚才制造的死循环导致的。
使用top -Hp 6993
查看进程下每个线程的状态,进一步定位问题
top - 10:20:26 up 77 days, 23:56, 4 users, load average: 0.66, 0.85, 0.88
Threads: 35 total, 1 running, 34 sleeping, 0 stopped, 0 zombie
%Cpu(s): 5.9 us, 15.1 sy, 0.0 ni, 78.8 id, 0.0 wa, 0.0 hi, 0.1 si, 0.0 st
KiB Mem : 32649012 total, 248888 free, 15987984 used, 16412140 buff/cache
KiB Swap: 16449532 total, 16026224 free, 423308 used. 14728536 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
7042 root 20 0 11.729g 437536 13676 R 99.9 1.3 0:36.36 java
6993 root 20 0 11.729g 437536 13676 S 0.0 1.3 0:00.00 java
6994 root 20 0 11.729g 437536 13676 S 0.0 1.3 0:03.16 java
6995 root 20 0 11.729g 437536 13676 S 0.0 1.3 0:00.07 java
6996 root 20 0 11.729g 437536 13676 S 0.0 1.3 0:00.07 java
6997 root 20 0 11.729g 437536 13676 S 0.0 1.3 0:00.07 java
6998 root 20 0 11.729g 437536 13676 S 0.0 1.3 0:00.07 java
6999 root 20 0 11.729g 437536 13676 S 0.0 1.3 0:00.08 java
可以看到7042线程占用了99.9%的cpu
获取7042的16进制表示结果:printf "%x" 7042
,得到1b82
使用jstack将线程信息下载到本地
jstack 7042> 7042.txt
sz 7042.txt
然后,使用jstack将线程状态信息导出
通过刚取到的线程id的十六进制结果,找到对应的调用栈。可以定位到出现异常的位置,应该是在CpuController.java:28
"Thread-4" #33 daemon prio=5 os_prio=0 tid=0x00007fa4780da000 nid=0x1b82 runnable [0x00007fa4c31c9000]
java.lang.Thread.State: RUNNABLE
at java.io.FileOutputStream.writeBytes(Native Method)
at java.io.FileOutputStream.write(FileOutputStream.java:326)
at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
- locked <0x00000005cdc3afa8> (a java.io.BufferedOutputStream)
at java.io.PrintStream.write(PrintStream.java:482)
- locked <0x00000005cdc3af88> (a java.io.PrintStream)
at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104)
- locked <0x00000005cdc3b0c8> (a java.io.OutputStreamWriter)
at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)
at java.io.PrintStream.newLine(PrintStream.java:546)
- locked <0x00000005cdc3af88> (a java.io.PrintStream)
at java.io.PrintStream.println(PrintStream.java:807)
- locked <0x00000005cdc3af88> (a java.io.PrintStream)
at com.yuxin.jstack.demo.CpuController.lambda$doLoop$0(CpuController.java:28)
at com.yuxin.jstack.demo.CpuController$$Lambda$335/1200917794.run(Unknown Source)
at java.lang.Thread.run(Thread.java:748)
找出死锁代码位置
执行以下代码
public void doDeadlock(){
new Thread(()->{
synchronized(lock1) {
try {Thread.sleep(1000);}catch(Exception e) {}
synchronized(lock2) {
System.out.println("线程1结束");
}
}
}) .start();
new Thread(()->{
synchronized(lock2) {
try {Thread.sleep(1000);}catch(Exception e) {}
synchronized(lock1) {
System.out.println("线程2结束");
}
}
}) .start();
}
使用jstack导出线程信息
可以看到有两个线程处于BLOCKED 状态
"Thread-5" #34 daemon prio=5 os_prio=0 tid=0x00007f234c42c800 nid=0x1cce waiting for monitor entry [0x00007f23964aa000]
java.lang.Thread.State: BLOCKED (on object monitor)
at com.yuxin.jstack.demo.CpuController.lambda$doDeadlock$2(CpuController.java:46)
- waiting to lock <0x00000005cebda938> (a java.lang.Object)
- locked <0x00000005cebda948> (a java.lang.Object)
at com.yuxin.jstack.demo.CpuController$$Lambda$336/1378440605.run(Unknown Source)
at java.lang.Thread.run(Thread.java:748)
"Thread-4" #33 daemon prio=5 os_prio=0 tid=0x00007f234c42b800 nid=0x1ccd waiting for monitor entry [0x00007f23973cb000]
java.lang.Thread.State: BLOCKED (on object monitor)
at com.yuxin.jstack.demo.CpuController.lambda$doDeadlock$1(CpuController.java:38)
- waiting to lock <0x00000005cebda948> (a java.lang.Object)
- locked <0x00000005cebda938> (a java.lang.Object)
at com.yuxin.jstack.demo.CpuController$$Lambda$335/1522210909.run(Unknown Source)
at java.lang.Thread.run(Thread.java:748)
信息的最后一部分,报出死锁问题
Found one Java-level deadlock:
=============================
"Thread-5":
waiting to lock monitor 0x00007f23696236c8 (object 0x00000005cebda938, a java.lang.Object),
which is held by "Thread-4"
"Thread-4":
waiting to lock monitor 0x00007f2369621e08 (object 0x00000005cebda948, a java.lang.Object),
which is held by "Thread-5"
Java stack information for the threads listed above:
===================================================
"Thread-5":
at com.yuxin.jstack.demo.CpuController.lambda$doDeadlock$2(CpuController.java:46)
- waiting to lock <0x00000005cebda938> (a java.lang.Object)
- locked <0x00000005cebda948> (a java.lang.Object)
at com.yuxin.jstack.demo.CpuController$$Lambda$336/1378440605.run(Unknown Source)
at java.lang.Thread.run(Thread.java:748)
"Thread-4":
at com.yuxin.jstack.demo.CpuController.lambda$doDeadlock$1(CpuController.java:38)
- waiting to lock <0x00000005cebda948> (a java.lang.Object)
- locked <0x00000005cebda938> (a java.lang.Object)
at com.yuxin.jstack.demo.CpuController$$Lambda$335/1522210909.run(Unknown Source)
at java.lang.Thread.run(Thread.java:748)
Found 1 deadlock.
综上可以找到在代码CpuController.java:38和CpuController.java:46的调用出现死锁问题
以上,即为通过jstack定位死循环、死锁的方式