CPU性能篇-系统CPU使用率很高，但找不到高CPU的应用-Day 04-EW帮帮网

1. 环境介绍

操作系统：CentOS 7.9

机器配置：8C16G

机器数量：2

必装软件：docker、sysstat、perf、ab等。

ab（apache bench）是一个常用的 HTTP 服务性能测试工具，这里用来模拟 Nginx 的客户端。

案例环境

可以看到，其中一台用作 Web 服务器，来模拟性能问题；另一台用作 Web 服务器的客户端，来给 Web 服务增加压力请求。使用两台虚拟机是为了相互隔离，避免“交叉感染”。

2. 软件包安装

两台机器都操作。这里我docker已经安装好了，就不演示了。

yum -y install sysstat perf

3. 操作与分析

3.1 VM1部署Nginx和PHP

[root@VM-13-112-centos tmp]# docker run --name nginx -p 10000:80 -itd feisky/nginx:sp
[root@VM-13-112-centos tmp]# docker ps -l
CONTAINER ID   IMAGE                                                         COMMAND                  CREATED         STATUS         PORTS                                     NAMES
d9a66dadfdfc   registry.cn-beijing.aliyuncs.com/sanhua-k8s/feisky_nginx:sp   "nginx -g 'daemon of…"   6 seconds ago   Up 5 seconds   0.0.0.0:10000->80/tcp, :::10000->80/tcp   nginx

[root@VM-13-112-centos tmp]# docker run --name phpfpm -itd --network container:nginx feisky/php-fpm:sp
[root@VM-13-112-centos tmp]# docker ps -l
CONTAINER ID   IMAGE                                                           COMMAND                  CREATED         STATUS         PORTS     NAMES
ea07b34fcc9f   registry.cn-beijing.aliyuncs.com/sanhua-k8s/feisky_php-fpm:sp   "php-fpm -F --pid /o…"   7 seconds ago   Up 4 seconds             phpfpm

3.2 VM2访问nginx

[root@VM-13-73-centos ~]# curl 10.13.13.112:10000
It works!

3.3 测试nginx的性能

3.3.1 第一次测试

在VM2运行ab命令，并发 100 个请求测试 Nginx 性能，总共测试 1000 个请求。

# 安装ab命令。ab命令在http-tools包里。
[root@VM-13-73-centos ~]# yum -y install httpd-tools

# 压测
[root@VM-13-73-centos ~]# ab -c 100 -n 1000 http://10.13.13.112:10000/
……省略部分输出
Requests per second:    267.47 [#/sec] (mean)
Time per request:       373.871 [ms] (mean)
……省略部分输出

从ab的输出结果我们可以看到，Nginx能承受的每秒平均请求数，只有267多一点，是不是感觉它的性能有点差呀。

那么，到底是哪里出了问题呢？我们再用 top 和 pidstat 来观察一下。

3.3.2 第二次测试

VM2，并发请求数改成 5，同时把请求时长设置为 10 分钟（-t 600）：

[root@VM-13-73-centos ~]# ab -c 5 -t 600 http://10.13.13.112:10000/

VM1执行top，观察系统CPU使用情况：

…………
%Cpu(s): 44.3 us, 13.7 sy,  0.0 ni, 40.8 id,  0.1 wa,  0.0 hi,  1.1 si,  0.0 st
…………
  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                                                                                                                                                                         
27641 101       20   0   33092   2196    776 S   8.0  0.0   0:22.07 nginx                                                                                              
27585 root      20   0  712180   6280   4212 S   6.3  0.0   0:17.35 containerd-shim                                                                                                                                                                               
26825 bin       20   0  336684   7688   1900 S   5.0  0.0   0:04.09 php-fpm                                                                                            
26829 bin       20   0  336684   7704   1916 S   4.7  0.0   0:04.13 php-fpm                                                                                            
26837 bin       20   0  336684   7704   1916 S   4.7  0.0   0:04.02 php-fpm                                                                                            
26841 bin       20   0  336684   7696   1908 S   4.7  0.0   0:04.05 php-fpm                                                                                            
26851 bin       20   0  336684   7688   1900 S   4.7  0.0   0:04.01 php-fpm                                                                                            
 8625 root      20   0 1434740  43704  10192 S   3.3  0.3 995:31.42 dockerd

从上述结果可以看到，我8C的VM，用户态的CPU使用率占到了44.3%，内核态的CPU使用率占用了13.7，空闲40.8，这明显是不合理的。

因为从进程列表看，相关的nginx、docker、php进程cpu占比都不高。

那这就非常奇怪了，目前使用top是看不到cpu占比较高的进程的。接下来使用pidstat看能不能有发现。

VM1，使用pidstat分析进程使用cpu情况：

[root@VM-13-112-centos ~]# pidstat 1 # 每隔1秒输出一组数据
Linux 3.10.0-1160.66.1.el7.x86_64 (VM-13-112-centos)    06/10/2025      _x86_64_        (8 CPU)

02:04:59 PM   UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
02:05:00 PM     1      2391    0.98    3.92    0.00    0.98    4.90     0  php-fpm
02:05:00 PM     1      2396    0.98    2.94    0.00    0.00    3.92     5  php-fpm
02:05:00 PM     1      2404    0.98    2.94    0.00    0.00    3.92     7  php-fpm
02:05:00 PM     1      2409    0.98    3.92    0.00    0.98    4.90     3  php-fpm
02:05:00 PM     1      2418    1.96    2.94    0.00    0.00    4.90     5  php-fpm
02:05:00 PM     0      8625    0.98    1.96    0.00    0.00    2.94     2  dockerd
02:05:00 PM     0     18860    0.00    0.98    0.00    0.00    0.98     2  pidstat
02:05:00 PM     0     27585    2.94    3.92    0.00    0.00    6.86     5  containerd-shim
02:05:00 PM   101     27641    1.96    5.88    0.00    0.00    7.84     5  nginx

从返回的结果来看，依然没有发现异常的进程，怎么办呢？重新执行top命令，看看有无遗漏什么关键信息。

VM1，使用top再次分析：

$ top
top - 04:58:24 up 14 days, 15:47,  1 user,  load average: 3.39, 3.82, 2.74
Tasks: 149 total,   6 running,  93 sleeping,   0 stopped,   0 zombie
%Cpu(s): 77.7 us, 19.3 sy,  0.0 ni,  2.0 id,  0.0 wa,  0.0 hi,  1.0 si,  0.0 st
KiB Mem :  8169348 total,  2543916 free,   457976 used,  5167456 buff/cache
KiB Swap:        0 total,        0 free,        0 used.  7363908 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 6947 systemd+  20   0   33104   3764   2340 S   4.0  0.0   0:32.69 nginx
 6882 root      20   0   12108   8360   3884 S   2.0  0.1   0:31.40 docker-containe
15465 daemon    20   0  336696  15256   7576 S   2.0  0.2   0:00.62 php-fpm
15466 daemon    20   0  336696  15196   7516 S   2.0  0.2   0:00.62 php-fpm
15489 daemon    20   0  336696  16200   8520 S   2.0  0.2   0:00.62 php-fpm
 6948 systemd+  20   0   33104   3764   2340 S   1.0  0.0   0:00.95 nginx
15006 root      20   0 1168608  65632  37536 S   1.0  0.8   9:51.09 dockerd
15476 daemon    20   0  336696  16200   8520 S   1.0  0.2   0:00.61 php-fpm
15477 daemon    20   0  336696  16200   8520 S   1.0  0.2   0:00.61 php-fpm
24340 daemon    20   0    8184   1616    536 R   1.0  0.0   0:00.01 stress
24342 daemon    20   0    8196   1580    492 R   1.0  0.0   0:00.01 stress
24344 daemon    20   0    8188   1056    492 R   1.0  0.0   0:00.01 stress
24347 daemon    20   0    8184   1356    540 R   1.0  0.0   0:00.01 stress
...

绪队列中居然有 6 个 Running 状态的进程（6 running），但并发请求数是 5。进程列表里， php-fpm 的数量也是 5，再加上 Nginx，好像同时有 6 个进程也并不奇怪，但是仔细看运行状态，php和nginx进程都是Sleep的，但有几个stress进程却是running的，貌似本次测试并没有启动该进程。

VM1,使用pidstat分析可疑进程：

[root@VM-13-112-centos ~]# pidstat -p 24342
Linux 3.10.0-1160.66.1.el7.x86_64 (VM-13-112-centos)    06/10/2025      _x86_64_        (8 CPU)

02:23:50 PM   UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command

居然没有内容？VM1使用ps看看这个进程怎么回事：

[root@VM-13-112-centos ~]# ps -ef |grep 24342
root      2782 32141  0 14:24 pts/0    00:00:00 grep --color=auto 24342

居然也没有，那就说明该进程已经不存在了。

vm1使用top查看系统状态：

…………
%Cpu(s): 42.9 us, 12.8 sy,  0.0 ni, 43.5 id,  0.0 wa,  0.0 hi,  0.9 si,  0.0 st
…………
 3489 bin       20   0  336684   7692   1904 S   5.0  0.0   0:01.47 php-fpm                                                                                            
 3497 bin       20   0  336684   7692   1904 R   5.0  0.0   0:01.42 php-fpm                                                                                            
 3502 bin       20   0  336684   7688   1900 S   5.0  0.0   0:01.44 php-fpm                                                                                            
 3485 bin       20   0  336684   7696   1908 S   4.7  0.0   0:01.44 php-fpm                                                                                            
 3511 bin       20   0  336684   7688   1900 S   4.7  0.0   0:01.41 php-fpm                                                                                            
 8625 root      20   0 1434740  43512  10304 S   3.7  0.3 996:04.35 dockerd  
 27642 101       20   0   33092   2192    772 S   0.7  0.0   0:04.51 nginx
16913 bin       20   0    8176    868    104 R   0.3  0.0   0:00.01 stress

结果还是跟之前一样，但这次我发现stress进程又出现了，进程的ID一直在变化，说明：

进程在不停地崩溃重启，比如因为段错误、配置错误等等，这时，进程在退出后可能又被监控系统自动重启了。
这些进程都是短时进程，也就是在其他应用内部通过 exec 调用的外面命令。这些命令一般都只运行很短的时间就会结束，你很难用 top 这种间隔时间比较长的工具发现（上面的案例，我们碰巧发现了）。

stress是一个常用的压力测试工具，它的 PID 在不断变化中，看起来像是被其他进程调用的短时进程。要想继续分析下去，还得找到它们的父进程。

VM1使用pstree查看进程间的关系：

注意：由于stress进程并不是一直存在的，所以要多次执行pstree，才能找到对应的信息。

[root@VM-13-112-centos ~]# pstree |grep stress
        |                 |         `-2*[php-fpm---sh---stress---stress]

从这里可以看到，stress 是被 php-fpm 调用的子进程，并且进程数量不止一个（这里是 2个，）。找到父进程后，我们能进入 app 的内部分析了。

3.4 源码分析

# 拷贝源码到本地
$ docker cp phpfpm:/app .

# grep 查找看看是不是有代码在调用stress命令
$ grep stress -r app
app/index.php:// fake I/O with stress (via write()/unlink()).
app/index.php:$result = exec("/usr/local/bin/stress -t 1 -d 1 2>&1", $output, $status);

找到了，果然是 app/index.php 文件中直接调用了 stress 命令。

再来看看 app/index.php 的源代码：

$ cat app/index.php
<?php
// fake I/O with stress (via write()/unlink()).
$result = exec("/usr/local/bin/stress -t 1 -d 1 2>&1", $output, $status);
if (isset($_GET["verbose"]) && $_GET["verbose"]==1 && $status != 0) {
  echo "Server internal error: ";
  print_r($output);
} else {
  echo "It works!";
}
?>

可以看到，源码里对每个请求都会调用一个 stress 命令，模拟 I/O 压力。从注释上看，stress 会通过 write() 和 unlink() 对 I/O 进程进行压测，看来，这应该就是系统 CPU 使用率升高的根源了。

不过，stress 模拟的是 I/O 压力，而之前在 top 的输出中看到的，却一直是用户 CPU 和系统 CPU 升高，并没见到 iowait 升高。这又是怎么回事呢？stress 到底是不是 CPU 使用率升高的原因呢？

从代码中可以看到，给请求加入 verbose=1 参数后，就可以查看 stress 的输出。

VM2

[root@VM-13-73-centos ~]# curl http://10.13.13.112:10000/?verbose=1
Server internal error: Array
(
    [0] => stress: info: [14910] dispatching hogs: 0 cpu, 0 io, 0 vm, 1 hdd
    [1] => stress: FAIL: [14911] (563) mkstemp failed: Permission denied
    [2] => stress: FAIL: [14910] (394) <-- worker 14911 returned error 1
    [3] => stress: WARN: [14910] (396) now reaping child worker processes
    [4] => stress: FAIL: [14910] (400) kill error: No such process
    [5] => stress: FAIL: [14910] (451) failed run completed in 0s
)

注意上面的报错：

mkstemp failed: Permission denied：这里说明没有权限执行。
failed run completed in 0s：这里说明stress命令根本没有执行成功。

从这里我们可以猜测，正是由于权限错误，大量的 stress 进程在启动时初始化失败，进而导致用户 CPU 使用率的升高。

3.5 VM1：使用perf分析CPU性能事件

# 记录性能事件，等待大约15秒后按 Ctrl+C 退出
$ perf record -g # 会在当前目录生成一个名为perf.data的文件。

# 查看报告
$ perf report

可以看到，stress 占了所有 CPU 时钟事件的 77%，而 stress 调用调用栈中比例最高的，是随机数生成函数 random()，看来它的确就是 CPU 使用率升高的元凶了。随后的优化就很简单了，只要修复权限问题，并减少或删除 stress 的调用，就可以减轻系统的 CPU 压力。

4. 扩展

上述案例中，由于CPU升高，是短时进程stress导致的，导致整个排查过程还是并不容易，这里可以使用execsnoop，execsnoop 就是一个专为短时进程设计的工具。

4.1 安装execsnoop

官网：https://github.com/brendangregg/perf-tools/blob/master/execsnoop

这个安装没有什么复杂的地方，压缩包里面都是可执行的二进制文件。

[root@VM-13-112-centos tmp]# tar xf perf-tools-1.0.tar.gz
[root@VM-13-112-centos tmp]# cd perf-tools-1.0/
[root@VM-13-112-centos perf-tools-1.0]# cd bin/
[root@VM-13-112-centos bin]# ll
total 0
lrwxrwxrwx 1 root root 16 Apr 18  2016 bitesize -> ../disk/bitesize
lrwxrwxrwx 1 root root 15 Apr 18  2016 cachestat -> ../fs/cachestat
lrwxrwxrwx 1 root root 12 Apr 18  2016 execsnoop -> ../execsnoop
lrwxrwxrwx 1 root root 19 Apr 18  2016 funccount -> ../kernel/funccount
lrwxrwxrwx 1 root root 19 Apr 18  2016 funcgraph -> ../kernel/funcgraph
lrwxrwxrwx 1 root root 20 Apr 18  2016 funcslower -> ../kernel/funcslower
lrwxrwxrwx 1 root root 19 Apr 18  2016 functrace -> ../kernel/functrace
lrwxrwxrwx 1 root root 12 Apr 18  2016 iolatency -> ../iolatency
lrwxrwxrwx 1 root root 10 Apr 18  2016 iosnoop -> ../iosnoop
lrwxrwxrwx 1 root root 12 Apr 18  2016 killsnoop -> ../killsnoop
lrwxrwxrwx 1 root root 16 Apr 18  2016 kprobe -> ../kernel/kprobe
lrwxrwxrwx 1 root root 12 Apr 18  2016 opensnoop -> ../opensnoop
lrwxrwxrwx 1 root root 22 Apr 18  2016 perf-stat-hist -> ../misc/perf-stat-hist
lrwxrwxrwx 1 root root 21 Apr 18  2016 reset-ftrace -> ../tools/reset-ftrace
lrwxrwxrwx 1 root root 11 Apr 18  2016 syscount -> ../syscount
lrwxrwxrwx 1 root root 17 Apr 18  2016 tcpretrans -> ../net/tcpretrans
lrwxrwxrwx 1 root root 16 Apr 18  2016 tpoint -> ../system/tpoint
lrwxrwxrwx 1 root root 14 Apr 18  2016 uprobe -> ../user/uprobe

4.2 参数介绍

[root@VM-13-112-centos bin]# ./execsnoop -h
USAGE: execsnoop [-hrt] [-a argc] [-d secs] [name]
                 -d seconds      # trace duration, and use buffers
                 -a argc         # max args to show (default 8)
                 -r              # include re-execs
                 -t              # include time (seconds)
                 -h              # this usage message
                 name            # process name to match (REs allowed)
  eg,
       execsnoop                 # watch exec()s live (unbuffered)
       execsnoop -d 1            # trace 1 sec (buffered)
       execsnoop grep            # trace process names containing grep
       execsnoop 'log$'          # filenames ending in "log"

See the man page and example file for more info.

4.3 使用execsnoop来查找瞬时进程

[root@VM-13-112-centos bin]# ./execsnoop -d 1 # 缓冲1秒钟的数据，结束再显示
Tracing exec()s for 1 seconds (buffered)...
Instrumenting sys_execve
   PID   PPID ARGS
 24281  24277 sleep 1
 24278  24194 awk -v o=1 -v opt_name=0 -v name= -v opt_duration=1 [...]
 24282   5101            <...>-24282 [000] d... 90019253.425790: execsnoop_sys_execve: (SyS_execve+0x0/0x30)
 24283  24282 /usr/local/bin/stress -t 1 -d 1
 24286   5122            <...>-24286 [000] d... 90019253.428146: execsnoop_sys_execve: (SyS_execve+0x0/0x30)
 24287   5105            <...>-24287 [005] d... 90019253.428517: execsnoop_sys_execve: (SyS_execve+0x0/0x30)
 24288  24286 /usr/local/bin/stress -t 1 -d 1
 24289  24287 /usr/local/bin/stress -t 1 -d 1
 24292   5107            <...>-24292 [000] d... 90019253.435719: execsnoop_sys_execve: (SyS_execve+0x0/0x30)
 24293  24292 /usr/local/bin/stress -t 1 -d 1
 24294   5117            <...>-24294 [000] d... 90019253.436863: execsnoop_sys_execve: (SyS_execve+0x0/0x30)
 24296  24294 /usr/local/bin/stress -t 1 -d 1
 24298   5122            <...>-24298 [001] d... 90019253.444465: execsnoop_sys_execve: (SyS_execve+0x0/0x30)
 24299  24298 /usr/local/bin/stress -t 1 -d 1
 24300   5101            <...>-24300 [006] d... 90019253.446250: execsnoop_sys_execve: (SyS_execve+0x0/0x30)
 24302  24300 /usr/local/bin/stress -t 1 -d 1
 24304   5105            <...>-24304 [000] d... 90019253.449206: execsnoop_sys_execve: (SyS_execve+0x0/0x30)
 24305  24304 /usr/local/bin/stress -t 1 -d 1
 24307   5107            <...>-24307 [005] d... 90019253.452040: execsnoop_sys_execve: (SyS_execve+0x0/0x30)
 24308  24307 /usr/local/bin/stress -t 1 -d 1
 24310   5117            <...>-24310 [005] d... 90019253.454536: execsnoop_sys_execve: (SyS_execve+0x0/0x30)
 24311  24310 /usr/local/bin/stress -t 1 -d 1
 24313   5122            <...>-24313 [002] d... 90019253.460887: execsnoop_sys_execve: (SyS_execve+0x0/0x30)
 24314  24313 /usr/local/bin/stress -t 1 -d 1
 24316   5101            <...>-24316 [006] d... 90019253.463370: execsnoop_sys_execve: (SyS_execve+0x0/0x30)
 24317  24316 /usr/local/bin/stress -t 1 -d 1
 24319   5105            <...>-24319 [001] d... 90019253.466382: execsnoop_sys_execve: (SyS_execve+0x0/0x30)
 24320  24319 /usr/local/bin/stress -t 1 -d 1
…………省略部分内容

这里捕获到了很多个stress相关的信息，可以看到他们的pid都不同，而且属于不同的主进程，但我php一共也就5个，不可能出来这么大一堆。所以还是之前分析的循环启动了大量的stress进程。

5. 总结

碰到常规问题无法解释的 CPU 使用率情况时，首先要想到有可能是短时应用导致的问题，比如有可能是下面这两种情况。

应用里直接调用了其他二进制程序，这些程序通常运行时间比较短，通过 top 等工具也不容易发现。

应用本身在不停地崩溃重启，而启动过程的资源初始化，很可能会占用相当多的 CPU。

对于这类进程，我们可以用 pstree 或者 execsnoop 找到它们的父进程，再从父进程所在的应用入手，排查问题的根源。

CPU性能篇-系统CPU使用率很高，但找不到高CPU的应用-Day 04