cpu使用率飚高实战分析（java应用）

前言：

有关于java应用CPU使用率超高的问题，已经有很多博客有过分析了。

无外乎就是，某个线程执行执行耗CPU的动作了。

我们主要的工作就是通过Linux命令和java相关命令找到具体的线程，并分析线程执行代码。

本文比较简单，就当是做一个记录。

1.准备工作 1.1 安装并启动docker tomcat

# 1.拉取tomcat镜像
hxw@hxwdeMacBook-Pro ~ % docker pull tomcat

# 2.完成后，启动一个tomcat容器
# tomcat默认启动端口为8080，将该端口映射到Mac的8088上
hxw@hxwdeMacBook-Pro ~ % docker run -p 8088:8080 -d tomcat

# 3.启动完成后，通过docker ps查看
hxw@hxwdeMacBook-Pro ~ % docker ps
CONTAINER ID   IMAGE           COMMAND                  CREATED        STATUS          PORTS                    NAMES
606ca0c7f783   tomcat:8.0.15   "catalina.sh run"        4 hours ago    Up 42 minutes   0.0.0.0:8088->8080/tcp   gracious_greider

# 4.验证tomcat启动
# 通过浏览器访问 localhost:8088，出现tomcat即可

1.2 准备war包，并拷贝到docker tomcat中

war包中有一个方法会引起CPU飙高，文章最后再做说明

# 1.准备war包，名称为SpringTest.war
# 2.拷贝到docker中
hxw@hxwdeMacBook-Pro ~ % docker cp SpringTest.war 606ca0c7f783:/usr/local/tomcat/webapps

# 3.重启tomcat
hxw@hxwdeMacBook-Pro ~ % docker restart 606ca0c7f783

2.分析CPU飙高问题

需要先调用tomcat中SpringTest.war相关方法，这里先不说明，文章最终再说

需要注意的是：以下操作都是在tomcat所在容器中进行的

2.1 进入tomcat容器，安装所需工具

# 1.通过docker exec命令进入
hxw@hxwdeMacBook-Pro ~ % docker exec -it 606ca0c7f783 /bin/bash
root@606ca0c7f783:/usr/local/tomcat# 

# 2.安装JDK，笔者这里默认没有jdk
root@606ca0c7f783:/usr/local/tomcat# apt-get update
root@606ca0c7f783:/usr/local/tomcat# apt-get install default-jdk
root@606ca0c7f783:/usr/local/tomcat# apt-get install less

主要使用的工具就是top和jdk（jstack）

less命令笔者所在tomcat也没有，也需要安装的（读者如果还需要其他命令，可自行安装，按照debain的方式来安装即可）

2.2 top分析进程CPU使用率

root@606ca0c7f783:/usr/local/tomcat# top 
top - 07:42:09 up  8:50,  0 users,  load average: 1.06, 0.41, 0.25
Tasks:   3 total,   0 running,   2 sleeping,   0 stopped,   0 zombie
%Cpu(s): 22.0 us, 49.9 sy,  0.0 ni, 28.1 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem:   2036420 total,  1895796 used,   140624 free,   140304 buffers
KiB Swap:  1048572 total,    64248 used,   984324 free.   817248 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                                                                          
    1 root      20   0 3318896 400936  13704 S 101.3 19.7   0:52.43 java                                                                                             
   58 root      20   0  169276  10464   3052 S   0.0  0.5   0:00.22 bash                                                                                             
 3186 root       0   0  170660   9408   4084 0   0.0  0.5   0:00.00 top

很容易就看到，PID=1的进程占用了101%的CPU，就是这个进程使CPU飙高的

2.3 查看使当前进程飙高的线程信息

# 这里的1，就是上面占用CPU的进程PID
root@606ca0c7f783:/usr/local/tomcat# top -H -p 1
  PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND                                                                                           
 3388 root      20   0 3319700 392824  13732 R 99.8 19.3   1:29.68 java                                                                                              
    1 root      20   0 3319700 392824  13732 S  0.0 19.3   0:00.05 java                                                                                              
   27 root      20   0 3319700 392824  13732 S  0.0 19.3   0:00.00 java                                                                                              
   28 root      20   0 3319700 392824  13732 S  0.0 19.3   0:02.65 java                                                                                              
   29 root      20   0 3319700 392824  13732 S  0.0 19.3   0:00.36 java                                                                                              
   30 root      20   0 3319700 392824  13732 S  0.0 19.3   0:00.37 java 

PID=3388的这个线程，占用了99.8%的CPU，那么我们直接分析这个线程就可以了

2.4 jstack命令查看进程栈信息

# 1.将进程号=1的进程栈信息导出到2.txt中
root@606ca0c7f783:/usr/local/tomcat# jstack 1 > 2.txt

# 2.将线程号转换为16进制（3388就是2.3中查出来的线程号）
root@606ca0c7f783:/usr/local/tomcat#  printf "%x\n" 3388
d3c

# 3.查询d3c的线程信息
root@606ca0c7f783:/usr/local/tomcat# grep d3c 2.txt 
"http-nio-8080-exec-7" daemon prio=10 tid=0x00000040b4005000 nid=0xd3c runnable [0x00000041100b6000]
   java.lang.Thread.State: RUNNABLE
        at java.io.FileOutputStream.writeBytes(Native Method)
        at java.io.FileOutputStream.write(FileOutputStream.java:345)
        at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
        at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
        - locked  (a java.io.BufferedOutputStream)
        at java.io.PrintStream.write(PrintStream.java:482)
        - locked  (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  (a java.io.OutputStreamWriter)
        at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)
        at java.io.PrintStream.newLine(PrintStream.java:546)
        - eliminated  (a java.io.PrintStream)
        at java.io.PrintStream.println(PrintStream.java:737)
        - locked  (a java.io.PrintStream)
        at org.apache.tomcat.util.log.SystemLogHandler.println(SystemLogHandler.java:237)
        # 在这里可以看到具体的代码块
        at com.example.controller.JvmTest.incre(JvmTest.java:21)

最终分析到是由于JvmTest.incre()方法导致的CPU飙高

2.5 通过代码验证分析正确性

既然分析到JvmTest.incre()方法导致的，我们直接来看对应代码    

@Controller
@RequestMapping("/jvmtest")
public class JvmTest {
    @RequestMapping(path = "/increment", method = RequestMethod.GET)
    public String incre() {
        int i = 0;
        for (int j = 0; j < 10000000; j++) {
            System.out.println(i++);
        }
        return "success";
    }
}

很容易看出来，就是这个for循环导致的。

总结：

java应用CPU飙高的问题并不难排查，按照这种标准方式来查，并没有解决不了的问题。