Jstack实战排查线上CPU占用过高的问题
閱讀本文約花費: 3 (分鐘)
1、通过top命令查看占用CPU过高的进程，信息如下：
shell> top
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
30718 root 20 0 3033296 333488 14084 S 96.7 17.7 8:32.75 java
3451 root 20 0 156164 7016 4184 S 1.7 0.4 0:31.61 sshd
32517 root 20 0 155028 5868 4184 S 1.0 0.3 0:07.26 sshd
9 root 20 0 0 0 0 S 0.7 0.0 231:10.83 rcu_sched
3537 root 20 0 162652 2984 1592 S 0.7 0.2 0:10.66 top
15625 root 20 0 162020 2276 1596 R 0.7 0.1 0:00.36 top
BashCopy
发现占用CPU最高的进程PID是：30718，此时我们知道这个java应用占用CPU最高，但不知道是应用中哪个地方的代码造成的。一个进程中包含若干线程，最想知道的就这个进程的资源占用详情了。此时仍使用top命令继续查看，格式：top -p pid -H。
shell> top -p 30718 -H PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 3427 root 20 0 3033296 335140 14088 R 92.7 17.8 16:49.21 java 30729 root 20 0 3033296 335140 14088 S 0.3 17.8 0:01.24 java 31081 root 20 0 3033296 335140 14088 S 0.3 17.8 0:00.28 java 30718 root 20 0 3033296 335140 14088 S 0.0 17.8 0:00.00 java 30719 root 20 0 3033296 335140 14088 S 0.0 17.8 0:19.10 java 30720 root 20 0 3033296 335140 14088 S 0.0 17.8 0:00.34 java 30721 root 20 0 3033296 335140 14088 S 0.0 17.8 0:00.33 java 30722 root 20 0 3033296 335140 14088 S 0.0 17.8 0:00.41 java 30723 root 20 0 3033296 335140 14088 S 0.0 17.8 0:00.00 java 30724 root 20 0 3033296 335140 14088 S 0.0 17.8 0:00.01 java 30725 root 20 0 3033296 335140 14088 S 0.0 17.8 0:00.00 java 30726 root 20 0 3033296 335140 14088 S 0.0 17.8 0:22.39 java
BashCopy
发现PID=3427的线程占用CPU最高，找到了线程号，就要想办法知道java的线程名称了。这时我们就需要用到jstack命令了，jstack pid，可以连接一个正在运行的进程，试一下看看。
shell> jstack 30718
2020-03-15 15:01:48
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.172-b11 mixed mode):
"http-nio-8080-Acceptor" #45 daemon prio=5 os_prio=0 tid=0x00007fc72c1c3000 nid=0x79b4 runnable [0x00007fc6fc2c2000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method)
at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:422)
at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:250)
- locked <0x00000000ff2ffca0> (a java.lang.Object)
at org.apache.tomcat.util.net.NioEndpoint.serverSocketAccept(NioEndpoint.java:461)
at org.apache.tomcat.util.net.NioEndpoint.serverSocketAccept(NioEndpoint.java:73)
at org.apache.tomcat.util.net.Acceptor.run(Acceptor.java:95)
at java.lang.Thread.run(Thread.java:748)
"sendText" #50 daemon prio=5 os_prio=0 tid=0x00007fc6e41b4000 nid=0xd63 runnable [0x00007fc6d7dfe000]
java.lang.Thread.State: RUNNABLE
at cn.fetosoft.rooster.demo.job.JobLiveMonitor$SendTextTask.run(JobLiveMonitor.java:63)
at java.lang.Thread.run(Thread.java:748)
"http-nio-8080-exec-9" #42 daemon prio=5 os_prio=0 tid=0x00007fc72cf06000 nid=0x79b0 waiting on condition [0x00007fc6fc5c5000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000ff3272b0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
.....
BashCopy
dump出了所有的java线程，此处只显示了部分线程信息。还可以通过命令将线程信息dump到文件中，从中可以看到线程的详细信息，其中nid就是线程的ID，是16进制的，把PID=3427转换成16进制。
shell> printf "%x\n" 3427 d63
BashCopy
使用grep过滤一下关键字为d63的线程
shell> jstack 30718 | grep d63 "sendText" #50 daemon prio=5 os_prio=0 tid=0x00007fc6e41b4000 nid=0xd63 runnable [0x00007fc6d7dfe000]
BashCopy
将线程信息dump到文件中
shell> jstack 30718 >> dump.txt
BashCopy
这样就找到了这个线程，根据线程名称“sendText”可以直接定位到java源码：
@OnOpen
public void openSession(Session session, @PathParam("jobCode") String code){
this.session = session;
jobCode = code;
isConn = true;
Thread thread = new Thread(new SendTextTask(session), "sendText");
thread.start();
}
class SendTextTask implements Runnable{
private Session tsession;
public SendTextTask(Session session){
this.tsession = session;
}
@Override
public void run() {
logger.info("Start sending messages >>>>>>>>>>>>>");
try{
while (isConn) {
String data = QUEUE.poll();
if(StringUtils.isNotBlank(data)) {
tsession.getBasicRemote().sendText(data);
}
}
}catch(IOException e){
logger.error("sendText", e);
}
if(!isConn){
logger.info("Stop sending messages >>>>>>>>>>>>>");
}
}
}
JavaCopy
从源码中可以看到，这里使用了一个线程从队列中获取信息，使用的while循环，会导致cpu一直空转，造成占用率很高，到此就查到问题点了。
从刚才的实战中也可以看到，创建线程的时候自定义名称很重要，对排查问题是非常的有用。