Jstack实战排查线上CPU占用过高的问题

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一直空转,造成占用率很高,到此就查到问题点了。
从刚才的实战中也可以看到,创建线程的时候自定义名称很重要,对排查问题是非常的有用。

发表评论

电子邮件地址不会被公开。 必填项已用*标注

Scroll Up