1.系统的CPU使用率,不仅包括进程用户态和内核态的运行,还包括中断处理,等待IO以及内核线程等等。所以,当你发现系统的CPU使用率很高的时候,不一定能找到相对应的高CPU使用率的进程
2.案例分析,排查定位不容易发现的高消耗CPU的进程
(1).案例准备工作:两台装有linux系统的虚拟机,一台用作web服务器,一台用作web服务器的客户端
(2).预先安装docker,sysstat,perf,ab等工具,ab装在客户端机器上,其他的安装在web服务器端
(3).在第一台机器(web服务器),执行docker命令,运行nginx和PHP:
docker run --name nginx -p 10000:80 -itd feisky/nginx:sp
docker run --name phpfpm -itd --network container:nginx feisky/php-fpm:sp
(4).在第二台机器上使用curl访问,确认nginx正常启动:
# 192.168.0.10 是第一台虚拟机的 IP 地址
$ curl http://192.168.0.10:10000/
It works!
(5).用ab测试nginx服务的性能,并发100个请求测试nginx性能,总共测试1000个请求:
# 并发 100 个请求测试 Nginx 性能,总共测试 1000 个请求
$ ab -c 100 -n 1000 http://192.168.0.10:10000/
This is ApacheBench, Version 2.3 <$Revision: 1706008 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd,
...
Requests per second: 87.86 [#/sec] (mean)
Time per request: 1138.229 [ms] (mean)
...
从ab的输出结果中,发现nginx能承受的每秒平均请求数只有87多一点,感觉性能有点差,那么,到底是哪出现的问题呢?我们再用top和pidstat观察下
(6).这次,在第二个终端,将测试的并发请求数改成5,同时把请求时长设为10分钟,便于测试中分析
$ ab -c 5 -t 600 http://192.168.0.10:10000/
(7).在第一个终端运行TOP命令,观察系统的CPU使用情况:
$ top
...
%Cpu(s): 80.8 us, 15.1 sy, 0.0 ni, 2.8 id, 0.0 wa, 0.0 hi, 1.3 si, 0.0 st
...
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
6882 root 20 0 8456 5052 3884 S 2.7 0.1 0:04.78 docker-containe
6947 systemd+ 20 0 33104 3716 2340 S 2.7 0.0 0:04.92 nginx
7494 daemon 20 0 336696 15012 7332 S 2.0 0.2 0:03.55 php-fpm
7495 daemon 20 0 336696 15160 7480 S 2.0 0.2 0:03.55 php-fpm
10547 daemon 20 0 336696 16200 8520 S 2.0 0.2 0:03.13 php-fpm
10155 daemon 20 0 336696 16200 8520 S 1.7 0.2 0:03.12 php-fpm
10552 daemon 20 0 336696 16200 8520 S 1.7 0.2 0:03.12 php-fpm
15006 root 20 0 1168608 66264 37536 S 1.0 0.8 9:39.51 dockerd
4323 root 20 0 0 0 0 I 0.3 0.0 0:00.87 kworker/u4:1
...
观察TOP的输出,CPU使用率最高的进程只有2.7%,看起来并不高,再看系统CPU使用率这一行,你会发现,系统整体CPU使用率是比较高的:用户CPU使用率达到80%,系统CPU使用率15.1%
为什么用户CPU使用率这么高呢,重新分析一下进程列表,并没有发现可疑进程
这时候,我们可以用pidstat,它可以用来分析进程的CPU使用情况
接下来,在第一台机器上,运行pidstat 命令
# 间隔 1 秒输出一组数据(按 Ctrl+C 结束)
$ pidstat 1
...
04:36:24 UID PID %usr %system %guest %wait %CPU CPU Command
04:36:25 0 6882 1.00 3.00 0.00 0.00 4.00 0 docker-containe
04:36:25 101 6947 1.00 2.00 0.00 1.00 3.00 1 nginx
04:36:25 1 14834 1.00 1.00 0.00 1.00 2.00 0 php-fpm
04:36:25 1 14835 1.00 1.00 0.00 1.00 2.00 0 php-fpm
04:36:25 1 14845 0.00 2.00 0.00 2.00 2.00 1 php-fpm
04:36:25 1 14855 0.00 1.00 0.00 1.00 1.00 1 php-fpm
04:36:25 1 14857 1.00 2.00 0.00 1.00 3.00 0 php-fpm
04:36:25 0 15006 0.00 1.00 0.00 0.00 1.00 0 dockerd
04:36:25 0 15801 0.00 1.00 0.00 0.00 1.00 1 pidstat
04:36:25 1 17084 1.00 0.00 0.00 2.00 1.00 0 stress
04:36:25 0 31116 0.00 1.00 0.00 0.00 1.00 0 atopacctd
...
从pidstat 输出中,并没有发现占用CPU很高的进程,即使所有进程的CPU使用率加起来,也不过21%,离80%还差的远
明明系统CPU使用率很高,达到了80%,为什么找不到占用CPU使用率高的进程呢?
很可能是因为前面的分析漏了一些关键信息,返回去分析TOP的输出,看看能不能有新的发现:
在第一台机器上,继续执行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
...
从top的输出,可以发现,就绪队列中居然有6个running状态的进程,是不是有点多呢?
回想下ab测试的参数,并发请求数是5,再看进程列表,php-fpm的数量也是5,再加上nginx,好像同时6个进程也不奇怪。
再仔细观察进程列表,发现php-fpm 的进程状态都是 S(休眠),而真正处于R状态的进程,却是几个stress进程,这几个stress进程比较奇怪,需要我们进一步分析
还是使用pidstat来分析这几个进程,并且使用 -p指定进程的PID.从上面的top中,找到几个进程的PID,用pidstat命令看一下它的CPU使用情况:
$ pidstat -p 24344
16:14:55 UID PID %usr %system %guest %wait %CPU CPU Command
奇怪,居然没有任何输出,再使用ps ,查看24344进程的状态:
# 从所有进程中查找 PID 是 24344 的进程
$ ps aux | grep 24344
root 9628 0.0 0.0 14856 1096 pts/0 S+ 16:15 0:00 grep --color=auto 24344
还是没有任何输出,现在终于发现,原来这个进程已经不存在了,所以pidstat没有任何输出,既然进程没了,那性能问题应该解决了吧,再用TOP命令确认下
$ top
...
%Cpu(s): 80.9 us, 14.9 sy, 0.0 ni, 2.8 id, 0.0 wa, 0.0 hi, 1.3 si, 0.0 st
...
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
6882 root 20 0 12108 8360 3884 S 2.7 0.1 0:45.63 docker-containe
6947 systemd+ 20 0 33104 3764 2340 R 2.7 0.0 0:47.79 nginx
3865 daemon 20 0 336696 15056 7376 S 2.0 0.2 0:00.15 php-fpm
6779 daemon 20 0 8184 1112 556 R 0.3 0.0 0:00.01 stress
...
从TOP输出中,发现用户CPU使用率还是高达80%,系统CPU接近15%,空闲只有2.8%,RUNNING状态的进程有Nginx,stress
可是,刚刚看到的stress进程不存在了,原来这次stress进程的PID跟前面不一样了,原来的PID 24344不见了,现在的是6779。
进程PID在变,说明什么呢?要么是进程在不断重启,要么就是全新的进程,无非也就是两个原因:
(1).第一个原因,进程在不停的崩溃重启,比如因为段错误,配置错误等等
(2).进程都是短时进程,也就是其他应用内部通过exec调用的外部命令,这些命令一般都只会运行很短时间就会结束,很难用top这种间隔时间比较长的工具发现(上面的案例,我们碰巧发现了)
至于stress,它是一个常用的压力测试工具,它的PID在不断变化中,看起来像是被其他进程调用的短时进程,要想继续分析下去,需要找到它们的父进程
用pstree就可以用树状形式显示所有进程之间的关系:
$ pstree | grep stress
|-docker-containe-+-php-fpm-+-php-fpm---sh---stress
| |-3*[php-fpm---sh---stress---stress]
从输出结果可以看出,streess是被php-fpm调用的子进程,并且数量不只一个(3个),找到父进程后,就能进入app内部分析了
当然我们应该去看看它的源码。运行下面的命令把源码拷贝到app目录,然后再执行grep查看是不是有代码在调用stress命令:
# 拷贝源码到本地
$ 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命令,模拟IO压力。从注释上看,stress会通过write()和unlink()对IO进行压测。看来,这就是CPU使用率升高的根源
不过,stress模拟的是IO压力,而之前top中输出的,却一直是用户CPU和系统CPU升高,并没有iowait升高。这又是怎么回事呢?Stress到底是不是CPU使用率升高的原因呢?
我们还得继续往下分析,给请求加上verbose=1参数后,就可以查看stress的输出。先试试看,在第二台机器运行:
$ curl http://192.168.0.10:10000?verbose=1
Server internal error: Array
(
[0] => stress: info: [19607] dispatching hogs: 0 cpu, 0 io, 0 vm, 1 hdd
[1] => stress: FAIL: [19608] (563) mkstemp failed: Permission denied
[2] => stress: FAIL: [19607] (394) <-- worker 19608 returned error 1
[3] => stress: WARN: [19607] (396) now reaping child worker processes
[4] => stress: FAIL: [19607] (400) kill error: No such process
[5] => stress: FAIL: [19607] (451) failed run completed in 0s
)
看错误消息,原来stress命令并没有成功,它因为权限问题失败退出了。看来,我们发现了PHP调用外部stress命令的bug:没有权限创建临时文件
从这里我们可以猜测,正是由于权限错误,大量的stress进程在启动时初始化失败,进而导致用户CPU使用率升高
前面,我们用了top.pidstat,pstress,没有发现大量的stress进程,那么,还有什么其他的工具可以用吗?
还记得之前的perf吗?它可以用来分析CPU性能事件,用在这里很合适,在第一个终端中运行perf record -g 命令,并等待一会(比如15秒)后按ctrc+c退出。然后再运行perf report查看
# 记录性能事件,等待大约 15 秒后按 Ctrl+C 退出
$ perf record -g
# 查看报告
$ perf report
这样就可以看到下图这个性能报告:
从报告输出中可以看到,stress调用栈中比例最高,是随机数生成random(),看来他的确就是CPU使用率升高的元凶了。
优化很简单,只要修复权限问题,并减少或删除stress调用,就可以减轻系统的CPU压力。
案例结束后,记得清理环境:
docker rm -f nginx php-fpm
总结:
碰到常规问题无法解释CPU使用率情况时,首先要想到的是短时应用导致的问题,比如有可能是下面这两种情况:
(1).应用里直接调用了其他二进制程序,这些程序通常运行时间比较短,通过top等工具也不容易发现
(2).应用本身在不停的崩溃重启,而启动过程的资源初始化,很可能会占用相当多的CPU
对于这类进程,我们可以用pstree或者execsnoop找到它们的父进程,再从父进程所在的应用入手,排查问题的根源