CPU使用率过高达到100%问题排查方法

最新推荐文章于 2024-10-08 09:05:09 发布

字恋狂#

最新推荐文章于 2024-10-08 09:05:09 发布

阅读量1.1k

点赞数 5

文章标签： java 服务器

本文链接：https://blog.csdn.net/weixin_38820691/article/details/136527294

版权

本文讲述了在企业商用环境中遇到服务CPU占用过高问题的解决过程，通过编写死循环代码模拟场景，使用TOP和jstack命令定位到异常进程和线程，最终确定问题源于死循环。

摘要由CSDN通过智能技术生成

最近在梳理自己曾经遇到过的一些问题，加深一下印象，温故而知新嘛，嘻嘻~

公司商用环境曾经出现过某个服务CPU异常的高，导致监控服务频繁的给运维和开发人员发送异常告警通知，甚至影响了业务的处理性能，此时我们需要定位到异常的原因，并进行解决。
通过这篇笔记，记录一下排查此类问题的思路和工具，毕竟好记性不如烂笔头（何况本人的记性并不好，哈哈

1. 准备工作

为了能模拟出CPU占用过高的现象，这里我们需要准备一段代码，在代码中实现一段死循环的逻辑（众所周知，死循环是会导致CPU异常高的一种场景），相关代码如下：

public class CpuTooHighTest {

    public static void main(String[] args) {
        System.out.println("application start");
        String str = "hello world!!!";

        int i = 0;
        boolean check = true;
        while (check) {
            //模拟业务逻辑，当符合某种条件时，将check设置为true，结束循环
            //这里为了实现死循环，所以直接写死一种永远不可能为true的判断 1==2
            if (1 == 2) {
                check = false;
            }
            i++;
        }

        System.out.println("application end");
    }

}

上面的一段代码中，由于 1==2 永远为false，所以check不会被设置为false，程序会一直执行while死循环。
将代码打包之后，丢到服务器中运行，我这里使用的命令如下：

java -cp cpu_too_high_test.jar CpuTooHighTest &

java -cp 命令可以指定类运行所需要依赖的其他类的路径，一般是jar包、类库之类的；
上面的命令中 cpu_too_high_test.jar 是我打包出来的jar包名称，CpuTooHighTest 是代码中的类名，所以最终会执行CpuTooHighTest 这个类中的 main 函数。
到这里，已经启动了一个存在死循环的程序，并且启动之后可以看到CPU里面飙升到了100（我这里是运行在电脑的虚拟机中）

2. 定位出CPU异常的进程

使用TOP命令，查看当前服务器内所有进程的CPU使用情况

top - 16:04:39 up  3:24,  2 users,  load average: 1.15, 1.26, 0.97
Tasks: 108 total,   1 running, 107 sleeping,   0 stopped,   0 zombie
%Cpu(s): 99.7 us,  0.3 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :  1863000 total,   743304 free,   253372 used,   866324 buff/cache
KiB Swap:  2097148 total,  2097148 free,        0 used.  1445188 avail Mem

   PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
 61001 root      20   0 2456208  22888  10492 S 99.3  1.2  18:28.63 java
     1 root      20   0  128016   6656   4164 S  0.0  0.4   0:01.20 systemd
     2 root      20   0       0      0      0 S  0.0  0.0   0:00.00 kthreadd
     4 root       0 -20       0      0      0 S  0.0  0.0   0:00.00 kworker/0:0H
     5 root      20   0       0      0      0 S  0.0  0.0   0:00.80 kworker/u256:0
     6 root      20   0       0      0      0 S  0.0  0.0   0:00.36 ksoftirqd/0
     7 root      rt   0       0      0      0 S  0.0  0.0   0:00.00 migration/0
     8 root      20   0       0      0      0 S  0.0  0.0   0:00.00 rcu_bh
     9 root      20   0       0      0      0 S  0.0  0.0   0:00.77 rcu_sched
    10 root       0 -20       0      0      0 S  0.0  0.0   0:00.00 lru-add-drain

很明显，可以发现 61001 这个 java 进程CPU使用率达到了 99.3%，罪魁祸首必然就是它了。

2.找出对应的线程

已经确定了61001这个进程，那我们接下来就可以使用命令找出对应的异常线程信息：

ps -mp {pid} -o THREAD,tid,time | sort -rn

将pid替换之后，执行结果如下：

[root@localhost apps]# ps -mp 61001 -o THREAD,tid,time | sort -rn
USER     %CPU PRI SCNT WCHAN  USER SYSTEM    TID     TIME
root     99.4  19    - -         -      -  61002 00:27:16
root     99.4   -    - -         -      -      - 00:27:16
root      0.0  19    - futex_    -      -  61010 00:00:00
root      0.0  19    - futex_    -      -  61009 00:00:00
root      0.0  19    - futex_    -      -  61008 00:00:00
root      0.0  19    - futex_    -      -  61007 00:00:00
root      0.0  19    - futex_    -      -  61006 00:00:00
root      0.0  19    - futex_    -      -  61005 00:00:00
root      0.0  19    - futex_    -      -  61004 00:00:00
root      0.0  19    - futex_    -      -  61003 00:00:00
root      0.0  19    - futex_    -      -  61001 00:00:00

可以发现，有一个线程CPU使用率很高，达到了99.4%，线程ID为61002，已经运行了 27分钟16秒

3.TID转换成16进制

将TID转换成16进制的命令如下：

printf "%x\n" tid

将tid替换成61002，执行结果如下：

[root@localhost apps]# printf "%x\n" 61002
ee4a

4.使用jstack命令查看进程信息

使用jstack命令，可以查看到进程的信息，通过tid过滤可以更方便的进行查找

jstack -pid | grep 16进制tid

替换pid、tid之后，执行命令：

[root@localhost apps]# jstack 61001 |grep ee4a
"main" #1 prio=5 os_prio=0 tid=0x00007f0264009800 nid=0xee4a runnable [0x00007f026b152000]

可以确定，当前线程依然还是存活状态，状态为 runnable
为了查看完整的信息，我们也可以将线程信息打印到文件中，同时也方便我们查找

jstack 61001 > 61001.txt

查看打印出的信息如下：

......
由于篇幅原因，省略前面部分内容

"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007f0264078000 nid=0xee4c in Object.wait() [0x00007f02546fd000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000000e3806c00> (a java.lang.ref.Reference$Lock)
        at java.lang.Object.wait(Object.java:502)
        at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
        - locked <0x00000000e3806c00> (a java.lang.ref.Reference$Lock)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

"main" #1 prio=5 os_prio=0 tid=0x00007f0264009800 nid=0xee4a runnable [0x00007f026b152000]
   java.lang.Thread.State: RUNNABLE
        at CpuTooHighTest.main(CpuTooHighTest.java:15)

"VM Thread" os_prio=0 tid=0x00007f026406e000 nid=0xee4b runnable

"VM Periodic Task Thread" os_prio=0 tid=0x00007f02640bb000 nid=0xee52 waiting on condition

JNI global references: 5

通过上面tid得到的16进制，定位到关键内容

"main" #1 prio=5 os_prio=0 tid=0x00007f0264009800 nid=0xee4a runnable [0x00007f026b152000]
   java.lang.Thread.State: RUNNABLE
        at CpuTooHighTest.main(CpuTooHighTest.java:15)

5.代码排查

到这里，我们便可以定位到CPU被 CpuTooHighTest.java 中15行的代码给占用了，也就是说15行前后的代码存在问题，我们再回过头来看看最开始写的测试代码，为了方便查看，这里给每行代码都加上了行号

1 public class CpuTooHighTest {
2
3    public static void main(String[] args) {
4        System.out.println("application start");
5        String str = "hello world!!!";
6
7        int i = 0;
8        boolean check = true;
9        while (check) {
10            //模拟业务逻辑，当符合某种条件时，将check设置为true，结束循环
11            //这里为了实现死循环，所以直接写死一种永远不可能为true的判断 1==2
12            if (1 == 2) {
13                check = false;
14            }
15            i++;
16        }
17
18        System.out.println("application end");
19    }
20
21 }