当你发现系统cpu使用率很高的时候,不一定能找到相对应的高cpu使用率进程,本文就是讨论这样问题的,以一个实例逐步分析,给出解决思路
案例实验环境说明
- 以nginx+php服务为例,使用docker跑对应的服务
案例操作及分析过程
# docker run -it -d --name nginx -p 10000:80 feisky/nginx:sp
# docker run -it -d --name phpfpm --network container:nginx feisky/php-fpm:sp
# curl http:10.0.11.12:10000 10.0.11.2是宿主机地址,访问返回下面这个表示容器运行成功
It works!
# ab -c100 -n1000 http://10.0.11.12:10000/
Concurrency Level: 100
Time taken for tests: 7.439 seconds
Complete requests: 1000
Failed requests: 0
Total transferred: 172000 bytes
HTML transferred: 9000 bytes
Requests per second: 134.43 [#/sec] (mean)
Time per request: 743.867 [ms] (mean)
Time per request: 7.439 [ms] (mean, across all concurrent requests)
Transfer rate: 22.58 [Kbytes/sec] received
nginx 每秒请求次数为134
# ab -c 5 -t 600 http://10.0.11.12:10000/
top命令:
top - 12:44:53 up 10:55, 3 users, load average: 5.15, 2.63, 1.07
Tasks: 213 total, 6 running, 115 sleeping, 0 stopped, 0 zombie
%Cpu(s): 72.4 us, 20.8 sy, 0.0 ni, 4.7 id, 0.0 wa, 0.0 hi, 2.0 si, 0.0 st
KiB Mem : 2017512 total, 415696 free, 548644 used, 1053172 buff/cache
KiB Swap: 2047996 total, 2047472 free, 524 used. 1288324 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
32360 systemd+ 20 0 33136 3760 2340 S 3.3 0.2 0:07.30 nginx
36648 daemon 20 0 336696 16456 8780 S 3.3 0.8 0:05.74 php-fpm
36656 daemon 20 0 336696 16456 8780 S 3.3 0.8 0:05.56 php-fpm
36649 daemon 20 0 336696 16520 8844 S 3.0 0.8 0:05.78 php-fpm
36664 daemon 20 0 336696 16456 8780 S 3.0 0.8 0:05.69 php-fpm
36677 daemon 20 0 336696 16456 8780 S 3.0 0.8 0:05.61 php-fpm
32276 root 20 0 109104 6324 4784 S 2.7 0.3 0:05.09 containerd-shim
36647 root 20 0 32896 6096 4848 S 2.3 0.3 0:04.56 ab
29885 root 20 0 1277672 105792 47732 S 1.3 5.2 1:03.54 dockerd
cpu占用最高的才3.3%,看起来并不高,但是整体cpu,us占72.4% ,sy占20.8%,id为4.7,,用户cpu占用率很高,达到72.4%,看看各个进程cpu占用率并不高,为啥总的us会很高,
# pidstat 1
2:49:44 PM UID PID %usr %system %guest %wait %CPU CPU Command
12:49:45 PM 0 29885 0.00 0.99 0.00 0.00 0.99 1 dockerd
12:49:45 PM 0 32276 1.98 0.00 0.00 0.00 1.98 0 containerd-shim
12:49:45 PM 101 32360 0.00 3.96 0.00 1.98 3.96 1 nginx
12:49:45 PM 101 32361 0.00 0.99 0.00 0.00 0.99 1 nginx
12:49:45 PM 0 56045 0.99 1.98 0.00 0.99 2.97 1 ab
12:49:45 PM 1 56046 0.00 2.97 0.00 1.98 2.97 0 php-fpm
12:49:45 PM 1 56051 0.99 1.98 0.00 0.99 2.97 0 php-fpm
12:49:45 PM 1 56057 0.00 2.97 0.00 1.98 2.97 0 php-fpm
12:49:45 PM 1 56059 0.00 2.97 0.00 0.99 2.97 0 php-fpm
12:49:45 PM 1 56072 0.00 2.97 0.00 1.98 2.97 0 php-fpm
12:49:45 PM 1 61853 0.99 0.00 0.00 0.00 0.99 1 stress
看各个进程cpu占用率加起来远小于us,us很高,却找不到哪个进程,这是啥原因?
- 回头看看top命令输出中tasks这个指标,running为6,感觉有点多,php-fpm进程才5个,加上nginx进程,看来也差不多,但是php和nginx都处于s,就是sleep状态,而处于R状态的出现了stress进程,好像没运行此应用啊,而且观察发现stress进程号时而出现,时而消失,pid在不断变化,这说明,这些进程在不停重启,或者新进程
原因基本是两种:
- 进程不停崩溃重启,进程退出,被监控系统自动重启
- 这些进程是短时进程,,就是在其他应用内部通过exec调用外面的命令,这命令短时就结束,所以很难用top这类工具发现
进程pid不断变化,看起来像是被其他进程调用的短时进程,要分析,需要找到它的父进程,可以使用pstree命令
# pstree |grep stress
| |-containerd-shim-+-php-fpm-+-2*[php-fpm---sh---stress]
| | | `-2*[php-fpm---sh---stress---stress]
看出stress是php调用的子进程,找到父进程之后,就去看app应用的代码
# docker cp phpfpm:/app .
# 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);
使用一些常用工具没发现大量stress进程,我们可以使用perf工具
perf record -g
perf report
进行进一步排查,当然需要一定的代码功底了,这里就不详细叙述了,最后定位是由于短时进程stress导致cpu us高,但整个分析很复杂,而且需要看懂代码逻辑,对于此类问题,有一个工具可以监控,就是execsnoop,项目地址:https://github.com/brendangregg/perf-tools/blob/master/execsnoop
总结
- 应用里面调用其他二进制程序,这些程序运行时间比较短,通过top类工具不易发现
- 应用本身不停崩溃重启,而启动过程的资源初始化,很可能会占用相当多的cpu资源
- 对于这类进程,可以用pstree,execsnoop工具进行分析