admin管理员组

文章数量:1607452

上一节我讲了 CPU 使用率是什么,并通过一个案例教你使用 top、vmstat、pidstat 等工具,排查高 CPU 使用率的进程,然后再使用 perf top 工具,定位应用内部函数的问题。不过就有人留言了,说似乎感觉高 CPU 使用率的问题,还是挺容易排查的。

那是不是所有 CPU 使用率高的问题,都可以这么分析呢?我想,你的答案应该是否定的。

回顾前面的内容,我们知道,系统的 CPU 使用率,不仅包括进程用户态和内核态的运行,还包括中断处理、等待 I/O 以及内核线程等。所以,当你发现系统的 CPU 使用率很高的时候,不一定能找到相对应的高 CPU 使用率的进程。

今天,我就用一个 Nginx + PHP 的 Web 服务的案例,带你来分析这种情况。

 

操作和分析


 首先,我们在第一个终端,执行下面的命令运行 Nginx 和 PHP 应用:

[root@localhost ~]# docker run --name nginx -p 10000:80 -itd feisky/nginx:sp
724f49267a44fe533de12be885940bb84ff109ccc4eef00d08a705d72e573bd8
[root@localhost ~]# docker run --name phpfpm -itd --network container:nginx feisky/php-fpm:sp
cc4ff1700f3e17da7757e2565542325b34853bba5c17f7d53626558699b66f71

然后,在第二个终端,使用 curl 访问 http://[VM1 的 IP]:10000,确认 Nginx 已正常启动。你应该可以看到 It works! 的响应。

# 192.168.179.99是第一台虚拟机的IP地址
[root@localhost ~]# curl 192.168.179.99:10000
It works!

接着,我们来测试一下这个 Nginx 服务的性能。在第二个终端运行下面的 ab 命令。要注意,与上次操作不同的是,这次我们需要并发 100 个请求测试 Nginx 性能,总共测试 1000 个请求。

# 并发100个请求测试Nginx性能,总共测试1000个请求
[root@localhost ~]# ab -c 100 -n 1000 http://192.168.179.99:10000/
This is ApacheBench, Version 2.3 <$Revision: 1430300 $>
...
Requests per second:    87.86 [#/sec] (mean)
Time per request:       1138.229 [ms] (mean)
...

从 ab 的输出结果我们可以看到,Nginx 能承受的每秒平均请求数,只有 87 多一点,是不是感觉它的性能有点差呀。那么,到底是哪里出了问题呢?我们再用 top 和 pidstat 来观察一下。

这次,我们在第二个终端,将测试的并发请求数改成 5,同时把请求时长设置为 10 分钟(-t 600)。这样,当你在第一个终端使用性能分析工具时, Nginx 的压力还是继续的。

继续在第二个终端运行 ab 命令:

[root@localhost ~]# ab -c 5 -t 600 http://192.168.179.99:10000/
This is ApacheBench, Version 2.3 <$Revision: 1430300 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech/
Licensed to The Apache Software Foundation, http://www.apache/

Benchmarking 192.168.179.99 (be patient)

然后,我们在第一个终端运行 top 命令,观察系统的 CPU 使用情况:

[root@localhost ~]# top
top - 17:22:58 up 1 day, 17:43,  5 users,  load average: 2.82, 1.98, 1.22
Tasks: 131 total,   6 running, 125 sleeping,   0 stopped,   0 zombie
%Cpu(s): 84.1 us, 13.3 sy,  0.0 ni,  1.4 id,  0.0 wa,  0.0 hi,  1.2 si,  0.0 st
KiB Mem :  1765672 total,   143216 free,   186828 used,  1435628 buff/cache
KiB Swap:   524284 total,   478172 free,    46112 used.  1267828 avail Mem 

   PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                          
 76584 101       20   0   33092   2200    776 S   2.7  0.1   0:01.41 nginx                                            
 79643 bin       20   0  336684   7696   1912 S   1.7  0.4   0:00.68 php-fpm                                          
 79648 bin       20   0  336684   7684   1900 S   1.7  0.4   0:00.70 php-fpm                                          
 79657 bin       20   0  336684   7696   1912 S   1.7  0.4   0:00.65 php-fpm                                          
 79664 bin       20   0  336684   7684   1900 S   1.7  0.4   0:00.69 php-fpm                                          
 79642 root      20   0   60024   3000   2240 S   1.3  0.2   0:00.58 ab                                               
 79667 bin       20   0  336684   7688   1904 R   1.3  0.4   0:00.65 php-fpm                                          
 17478 root      20   0  627164  71076  27432 S   1.0  4.0   3:18.93 dockerd                                          
 76541 root      20   0  109096   3736   2700 S   1.0  0.2   0:00.50 containerd-shim                                  
 76611 root      20   0  336300  33092  27696 S   0.3  1.9   0:00.21 php-fpm                                          
 89786 bin       20   0    8176    600    104 R   0.3  0.0   0:00.01 stress                                           
 89788 bin       20   0    8176    604    104 R   0.3  0.0   0:00.01 stress                                           
     1 root      20   0  125600   2712   1564 S   0.0  0.2   0:18.39 systemd          

观察 top 输出的进程列表可以发现,CPU 使用率最高的进程也只不过才 2.7%,看起来并不高。

然而,再看系统 CPU 使用率( %Cpu )这一行,你会发现,系统的整体 CPU 使用率是比较高的:用户 CPU 使用率(us)已经到了 84.1%,系统 CPU 为 13.3%,而空闲 CPU (id)则只有 1.4%。

为什么用户 CPU 使用率这么高呢?我们再重新分析一下进程列表,看看有没有可疑进程:

  1. Nginx 和 php-fpm 是运行 Web 服务的,它们会占用一些 CPU 也不意外,并且 1% 的 CPU 使用率也不算高
  2. 再往下看,后面的进程呢,只有 0.3% 的 CPU 使用率,看起来不太像会导致用户 CPU 使用率达到 80%

那就奇怪了,明明用户 CPU 使用率都 80% 了,可我们挨个分析了一遍进程列表,还是找不到高 CPU 使用率的进程。看来 top 是不管用了,那还有其他工具可以查看进程 CPU 使用情况吗?不知道你记不记得我们的老朋友 pidstat,它可以用来分析进程的 CPU 使用情况。 

接下来,我们还是在第一个终端,运行 pidstat 命令:

# 间隔1秒输出一组数据(按Ctrl+C结束)
[root@localhost ~]# pidstat 1
...
05:26:08 PM   UID       PID    %usr %system  %guest    %CPU   CPU  Command
05:26:09 PM     0      3026    0.00    1.00    0.00    1.00     1  pidstat
05:26:09 PM     0     29992    0.00    1.00    0.00    1.00     1  kworker/1:0
05:26:09 PM     0     76541    0.00    1.00    0.00    1.00     0  containerd-shim
05:26:09 PM   101     76584    0.00    3.00    0.00    3.00     0  nginx
05:26:09 PM     0     79642    0.00    1.00    0.00    1.00     1  ab
05:26:09 PM     1     79643    0.00    2.00    0.00    2.00     1  php-fpm
05:26:09 PM     1     79648    0.00    1.00    0.00    1.00     0  php-fpm
05:26:09 PM     1     79657    0.00    1.00    0.00    1.00     0  php-fpm
05:26:09 PM     1     79664    0.00    2.00    0.00    2.00     0  php-fpm
05:26:09 PM     1     79667    0.00    1.00    0.00    1.00     1  php-fpm
...

观察一会儿,你是不是发现,所有进程的 CPU 使用率也都不高啊,最高的 pidstat 和  kworker/1:0 也只有 1% 和 1%,即使所有进程的 CPU 使用率都加起来,也不过是 21%,离 80% 还差得远呢!

最早的时候,我碰到这种问题就完全懵了:明明用户 CPU 使用率已经高达 80%,但我却怎么都找不到是哪个进程的问题。到这里,你也可以想想,你是不是也遇到过这种情况?还能不能再做进一步的分析呢?

后来我发现,会出现这种情况,很可能是因为前面的分析漏了一些关键信息。你可以先暂停一下,自己往上翻,重新操作检查一遍。或者,我们一起返回去分析 top 的输出,看看能不能有新发现。

现在,我们回到第一个终端,重新运行 top 命令,并观察一会儿:

[root@localhost ~]# top
top - 17:31:22 up 1 day, 17:51,  6 users,  load average: 6.39, 5.64, 3.42
Tasks: 131 total,   6 running, 124 sleeping,   0 stopped,   0 zombie
%Cpu(s): 80.4 us, 11.7 sy,  0.0 ni,  7.3 id,  0.0 wa,  0.0 hi,  0.7 si,  0.0 st
KiB Mem :  1765672 total,   103596 free,   187828 used,  1474248 buff/cache
KiB Swap:   524284 total,   478192 free,    46092 used.  1256084 avail Mem 

   PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                          
 76584 101       20   0   33092   2200    776 S   2.7  0.1   0:15.00 nginx                                            
 79643 bin       20   0  336684   7708   1924 S   1.7  0.4   0:08.76 php-fpm                                          
 79657 bin       20   0  336684   7704   1920 S   1.7  0.4   0:08.56 php-fpm                                          
 79642 root      20   0   60024   4312   2320 S   1.3  0.2   0:07.06 ab                                               
 79648 bin       20   0  336684   7692   1908 S   1.3  0.4   0:08.79 php-fpm                                          
 79664 bin       20   0  336684   7696   1912 S   1.3  0.4   0:08.64 php-fpm                                          
 79667 bin       20   0  336684   7700   1916 S   1.3  0.4   0:08.48 php-fpm                                          
 76541 root      20   0  109096   3696   2708 S   1.0  0.2   0:05.49 containerd-shim                                  
 17478 root      20   0  627164  71076  27432 S   0.7  4.0   3:22.84 dockerd                                          
   962 root      20   0  562408    812    480 S   0.3  0.0   0:42.79 tuned                                            
 76652 bin       20   0    8176    600    104 R   0.3  0.0   0:00.01 stress                                           
 76653 bin       20   0    8172    596    104 R   0.3  0.0   0:00.01 stress                                           
 76660 bin       20   0    8172    600    104 R   0.3  0.0   0:00.01 stress                                           
     1 root      20   0  125600   2712   1564 S   0.0  0.2   0:18.41 systemd                                          
     2 root      20   0       0      0      0 S   0.0  0.0   0:00.70 kthreadd                                         
     3 root      20   0       0      0      0 S   0.0  0.0   0:20.88 ksoftirqd/0                                      
     5 root       0 -20       0      0      0 S   0.0  0.0   0:00.00 kworker/0:0H  

这次从头开始看 top 的每行输出,咦?Tasks 这一行看起来有点奇怪,就绪队列中居然有 6 个 Running 状态的进程(6 running),是不是有点多呢?

回想一下 ab 测试的参数,并发请求数是 5。再看进程列表里, php-fpm 的数量也是 5,再加上 Nginx,好像同时有 6 个进程也并不奇怪。但真的是这样吗?

再仔细看进程列表,这次主要看 Running(R) 状态的进程。你有没有发现, Nginx 和所有的 php-fpm 都处于 Sleep(S)状态,而真正处于 Running(R)状态的,却是几个 stress 进程。这几个 stress 进程就比较奇怪了,需要我们做进一步的分析。

我们还是使用 pidstat 来分析这几个进程,并且使用 -p 选项指定进程的 PID。首先,从上面 top 的结果中,找到这几个进程的 PID。比如,先随便找一个 24344,然后用 pidstat 命令看一下它的 CPU 使用情况:

[root@localhost ~]# pidstat -p  76652
Linux 3.10.0-693.el7.x86_64 (localhost.localdomain) 	11/11/2020 	_x86_64_	(2 CPU)

05:32:55 PM   UID       PID    %usr %system  %guest    %CPU   CPU  Command

奇怪,居然没有任何输出。难道是 pidstat 命令出问题了吗?之前我说过,在怀疑性能工具出问题前,最好还是先用其他工具交叉确认一下。那用什么工具呢? ps 应该是最简单易用的。我们在终端里运行下面的命令,看看 24344 进程的状态:

# 从所有进程中查找PID是76652的进程
[root@localhost ~]# ps -aux | grep 76652
root      89099  0.0  0.0 112660   968 pts/1    S+   17:33   0:00 grep --color=auto 76652

还是没有输出。现在终于发现问题,原来这个进程已经不存在了,所以 pidstat 就没有任何输出。既然进程都没了,那性能问题应该也跟着没了吧。我们再用 top 命令确认一下:

[root@localhost ~]# top
top - 17:34:34 up 1 day, 17:55,  4 users,  load average: 1.40, 3.79, 3.14
Tasks: 126 total,   6 running, 120 sleeping,   0 stopped,   0 zombie
%Cpu(s): 78.4 us, 13.2 sy,  0.0 ni,  7.5 id,  0.0 wa,  0.0 hi,  0.8 si,  0.0 st
KiB Mem :  1765672 total,   117032 free,   182640 used,  1466000 buff/cache
KiB Swap:   524284 total,   478196 free,    46088 used.  1273212 avail Mem 

   PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                          
 76584 101       20   0   33092   2200    776 S   2.7  0.1   0:16.71 nginx                                            
 89102 bin       20   0  336684   7708   1924 S   2.0  0.4   0:00.17 php-fpm                                          
 89114 bin       20   0  336684   7684   1900 S   1.7  0.4   0:00.16 php-fpm                                          
 89123 bin       20   0  336684   7684   1900 S   1.7  0.4   0:00.16 php-fpm                                          
 89128 bin       20   0  336684   7684   1900 S   1.7  0.4   0:00.15 php-fpm                                          
 89106 bin       20   0  336684   7688   1904 S   1.3  0.4   0:00.16 php-fpm                                          
 89101 root      20   0   60024   3000   2240 S   1.0  0.2   0:00.13 ab                                               
 17478 root      20   0  627164  71076  27432 S   0.7  4.0   3:23.38 dockerd                                          
 76541 root      20   0  109096   3712   2708 S   0.7  0.2   0:06.13 containerd-shim                                  
   361 root      20   0   36968   5768   5544 S   0.3  0.3   0:13.45 systemd-journal                                  
 91779 bin       20   0    8172   1120    104 R   0.3  0.1   0:00.01 stress                                           
 91781 bin       20   0    8172    600    104 R   0.3  0.0   0:00.01 stress                                           
 91787 bin       20   0    8172    856    104 R   0.3  0.0   0:00.01 stress                                           
     1 root      20   0  125600   2712   1564 S   0.0  0.2   0:18.41 systemd                                          
     2 root      20   0       0      0      0 S   0.0  0.0   0:00.70 kthreadd                                         
     3 root      20   0       0      0      0 S   0.0  0.0   0:20.91 ksoftirqd/0                                      
     5 root       0 -20       0      0      0 S   0.0  0.0   0:00.00 kworker/0:0H  

好像又错了。结果还跟原来一样,用户 CPU 使用率还是高达 80.9%,系统 CPU 接近 15%,而空闲 CPU 只有 2.8%,Running 状态的进程有 Nginx、stress 等。

可是,刚刚我们看到 stress 进程不存在了,怎么现在还在运行呢?再细看一下 top 的输出,原来,这次 stress 进程的 PID 跟前面不一样了,原来的 PID  76652 不见了,现在的是 91779。

进程的 PID 在变,这说明什么呢?在我看来,要么是这些进程在不停地重启,要么就是全新的进程,这无非也就两个原因:

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

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

要怎么查找一个进程的父进程呢?没错,用 pstree  就可以用树状形式显示所有进程之间的关系:

[root@localhost ~]# pstree | grep stress
        |            |-containerd-shim-+-php-fpm-+-4*[php-fpm---sh---stress---stress]

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

首先,当然应该去看看它的源码。运行下面的命令,把案例应用的源码拷贝到 app 目录,然后再执行 grep 查找是不是有代码再调用 stress 命令:

# 拷贝源码到本地
[root@localhost ~]# docker exec -it phpfpm /bin/bash
root@724f49267a44:/app# pwd
/app
root@724f49267a44:/app# ls
404.html  index.php  ok.php  phpinfo.php
root@724f49267a44:/app# exit
exit
[root@localhost ~]# docker cp phpfpm:/app .
[root@localhost ~]# ls
anaconda-ks.cfg  app

# grep 查找看看是不是有代码在调用stress命令
[root@localhost ~]# 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 的源代码:

[root@localhost ~]# 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 的输出。你先试试看,在第二个终端运行:

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

看错误消息 mkstemp failed: Permission denied ,以及 failed run completed in 0s。原来 stress 命令并没有成功,它因为权限问题失败退出了。看来,我们发现了一个 PHP 调用外部 stress 命令的 bug:没有权限创建临时文件。

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

分析出问题来源,下一步是不是就要开始优化了呢?当然不是!既然只是猜测,那就需要再确认一下,这个猜测到底对不对,是不是真的有大量的 stress 进程。该用什么工具或指标呢?

我们前面已经用了 top、pidstat、pstree 等工具,没有发现大量的 stress 进程。那么,还有什么其他的工具可以用吗?

# 记录性能事件,等待大约15秒后按 Ctrl+C 退出
$ perf record -g

# 查看报告
$ perf report

这样,你就可以看到下图这个性能报告:

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

 

小结


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

  • 第一,应用里直接调用了其他二进制程序,这些程序通常运行时间比较短,通过 top 等工具也不容易发现。
  • 第二,应用本身在不停地崩溃重启,而启动过程的资源初始化,很可能会占用相当多的 CPU。

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

本文标签: 找不到率很高系统LinuxCPU