上一节我们学习了CPU使用率是什么,并且使用案例练习使用top、vmstat、pidstat等工具,排查高CPU使用率的进程,然后再使用perf top工具定位应用内部函数的问题。那么,高CPU使用率的问题是不是就很容易排查呢,实际上不是的;

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

这次,我们还是用一个Nginx + PHP的Web服务的案例,来分析这种情况;

案例分析

准备

今天依然是探究系统CPU使用率高的情况,因此这次实验的准备工作,与上一节基本相同,区别是在于案例使用的docker镜像不同;

以下案例基于Ubuntu 18.04, 同样适用于其他的Linux系统。使用的案例环境如下所示:

  • 机器配置: 2CPU, 8GB内存

  • 预先安装docker、sysstat、perf、ab等工具

ab(apache bench)是一个常见的HTTP服务性能测试工具,这里用来模拟Nginx的客户端;

由于Nginx和PHP配置比较麻烦,将他们打包成了两个Docker镜像,这样,只需要运行两个容器,就可以得到模拟环境;

image-20230716230804611

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

操作和分析

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

1
2
docker run --name nginx -p 10000:80 -itd feisky/nginx:sp
docker run --name phpfpm -itd --network container:nginx feisky/php-fpm:sp

image-20230719183005666

然后在终端二,使用curl访问http://192.168.44.138:10000/, 确认Nginx已经正常启动。正常可以看到It works!的响应;

image-20230719183227603

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

1
2
# 并发100个请求测试Nginx的性能,总共测试1000个请求
ab -c 100 -n 1000 http://192.168.44.138:10000/
 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
root@morn:/home/bomir1# ab -c 100 -n 1000 http://192.168.44.138:10000/
This is ApacheBench, Version 2.3 <$Revision: 1807734 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/
...
Requests per second:    162.96 [#/sec] (mean)
Time per request:       613.644 [ms] (mean)
Time per request:       6.136 [ms] (mean, across all concurrent requests)
Transfer rate:          27.37 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    1   2.3      0      11
Processing:    59  583  92.3    603     698
Waiting:       55  583  92.3    603     698
Total:         70  584  90.3    603     702

Percentage of the requests served within a certain time (ms)
  50%    603
  66%    617
  75%    624
  80%    628
  90%    639
  95%    648
  98%    658
  99%    669
 100%    702 (longest request)

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

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

1
ab -c 5 -t 600 http://192.168.44.138:10000/

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

image-20230719185642818

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

然而,再看系统CPU使用率,系统整体CPU利用率是比较高的:用户CPU使用率 (us)已经到了61.2%, 系统CPU为28.3, 而空闲CPU(id)则只有5.4%。

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

  • dockerd进程是用来运行容器的,1.7%的CPU看起来正常;
  • Nginx和php-fpm是运行Web服务的,他们回占用一些CPU也不意外,并且3.7%的CPU使用率也不算高;
  • 后面的进程,只有0.3%的CPU使用率,并且看起来不像是会导致用户CPU使用率到达61.2%

这就比较奇怪了,明明用户CPU使用率已经到了61.2%, 但是我们找了一圈进程列表,还是没有找到高CPU使用率的进程。看来是top不管用了,那我们还有其他工具可以查看进程CPU使用情况。如pidstat, 可以用它来分析进程的CPU使用情况。

image-20230723220643787

观察了一下,所有进程的CPU使用率也都不高啊,最高的nginx和phph-fpm也只有5%和4%, 即使列表所有进程的CPU使用率加起来也才32%, 离61%差的也有点多呢;

以前的时候,碰到这种问题就完全懵了:明明CPU使用率已经高达64.8%, 但是怎么都找不到是哪个进程的问题,这类情况能否做进一步的分析呢?

再次分析

后来会发现,会出现这种情况,很可能是因为前面的分析漏掉了一些关键信息;我们可以一起返回去分析top的输出,看看能不能有一些新发现;

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
Tasks: 300 total,   7 running, 221 sleeping,   0 stopped,   1 zombie
%Cpu(s): 63.2 us, 27.8 sy,  0.0 ni,  4.2 id,  0.0 wa,  0.0 hi,  4.7 si,  0.0 st
KiB Mem :  8117340 total,  5364656 free,  1018236 used,  1734448 buff/cache
KiB Swap:  3999740 total,  3999740 free,        0 used.  6785400 avail Mem 

   PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                                                                     
  3908 systemd+  20   0   33136   3772   2448 S   5.6  0.0   0:29.87 nginx                                                                                              
 23619 daemon    20   0  336696  16272   8596 S   3.6  0.2   0:07.81 php-fpm                                                                                                                                    
 23624 daemon    20   0  336696  16208   8532 S   3.6  0.2   0:07.81 php-fpm                                                                                                                                    
 23631 daemon    20   0  336696  16272   8596 S   3.6  0.2   0:07.73 php-fpm                                                                                                                                    
  3850 root      20   0  720500   9092   7256 S   3.3  0.1   0:21.12 containerd-shim                                                                                                                            
 23644 daemon    20   0  336696  16272   8596 S   3.3  0.2   0:07.75 php-fpm                                                                                                                                    
 23634 daemon    20   0  336696  16208   8532 S   3.0  0.2   0:07.78 php-fpm                                                                                                                                    
  1145 root      20   0 1875532  78340  52612 S   2.3  1.0   0:16.83 dockerd                                                                                                                                    
     9 root      20   0       0      0      0 R   2.0  0.0   0:09.20 ksoftirqd/0                                                                                                                                
  1702 root      20   0  720756   9968   7548 S   0.7  0.1   0:03.35 containerd-shim                                                                                                                            
  1026 redis     20   0   51452   3668   2596 S   0.3  0.0   0:31.76 redis-server                                                                                                                               
  3534 root      20   0       0      0      0 I   0.3  0.0   0:00.58 kworker/u256:1-                                                                                                                            
  3586 root      20   0       0      0      0 I   0.3  0.0   0:00.62 kworker/0:1-eve                                                                                                                            
  3806 root      20   0       0      0      0 I   0.3  0.0   0:00.86 kworker/1:2-eve                                                                                                                            
  3956 root      20   0  336312  46700  39300 S   0.3  0.6   0:01.41 php-fpm                                                                                                                                    
 23618 bomir     20   0   44228   4180   3332 R   0.3  0.1   0:00.74 top                                                                                                                                        
     1 root      20   0  160056   9348   6712 S   0.0  0.1   0:03.14 systemd                                                                                                                                    
     2 root      20   0       0      0      0 S   0.0  0.0   0:00.02 kthreadd                                                                                                                                   
     3 root       0 -20       0      0      0 I   0.0  0.0   0:00.00 rcu_gp                                                                                                                                     
     4 root       0 -20       0      0      0 I   0.0  0.0   0:00.00 rcu_par_gp                                                                                                                                 
     6 root       0 -20       0      0      0 I   0.0  0.0   0:00.00 kworker/0:0H-kb                                                                                                                            
     8 root       0 -20       0      0      0 I   0.0  0.0   0:00.00 mm_percpu_wq                                                                                                                               
    10 root      20   0       0      0      0 I   0.0  0.0   0:12.66 rcu_sched                                                                                                                                  
    11 root      rt   0       0      0      0 S   0.0  0.0   0:00.32 migration/0                                                                                                                                
    12 root     -51   0       0      0      0 S   0.0  0.0   0:00.00 idle_inject/0                                                                                                                              
    14 root      20   0       0      0      0 S   0.0  0.0   0:00.00 cpuhp/0                                                                                                                                    
    15 root      20   0       0      0      0 S   0.0  0.0   0:00.00 cpuhp/1                                                                                                                                    
    16 root     -51   0       0      0      0 S   0.0  0.0   0:00.00 idle_inject/1                                                                                                                              
    17 root      rt   0       0      0      0 S   0.0  0.0   0:01.15 migration/1                                                                                                                                
    18 root      20   0       0      0      0 S   0.0  0.0   0:00.57 ksoftirqd/1                                                                                                                                
    20 root       0 -20       0      0      0 I   0.0  0.0   0:00.00 kworker/1:0H-kb                                                                                                                            
    21 root      20   0       0      0      0 S   0.0  0.0   0:00.00 kdevtmpfs                                                                                                                                  
    22 root       0 -20       0      0      0 I   0.0  0.0   0:00.00 netns                                                                                                                                      
    23 root      20   0       0      0      0 S   0.0  0.0   0:00.00 rcu_tasks_kthre                                                                                                                            
    24 root      20   0       0      0      0 S   0.0  0.0   0:00.00 kauditd 

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

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

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

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

image-20230723223736464

没有什么输出,我们再用ps工具去交叉确认一下, 使用ps去查看进程是简单易用的,在终端里面运行下面的命令,看看24344进程的状态:

image-20230723223944587

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

image-20230723224235127

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

可是,我们刚刚看到的stress进程不存在了,怎么现在还在运行呢?细看一下, stree进程的PID已经发生变化了。

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

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

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

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

image-20230723225652956

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

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

image-20230723230203683

找到了,果然是app/index.php文件里面直接调用了stress命令;

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

1
2
3
4
5
6
7
8
9
<?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使用率升高的根源了;

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

我们还得继续往下走,从代码中可以看到,给请求加入verbose=1参数后,就可以查看stress的输出了。我们先试试看,在终端二运行:

curl http://192.168.44.138:10000/?verbose=1

image-20230723231805862

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

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

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

可以使用上一节提到的perf, 它可以用来分析CPU性能事件,用在这里就很合适。依旧在第一个终端中运行perf record -g命令,并等待一会儿(比如15s)后按Ctrl + C退出,然后再用perf report查看报告;

1
2
3
4
# 记录性能事件,等待大约15秒按Ctrl + C退出
perf record -g
# 查看报告
perf report

image-20230723232913925

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

当然,实际生产环境中的问题远比这个case复杂,在你找到触发瓶颈的命令行后,却可能发现,这个外部命令的调用过程实际是应用核心逻辑的一部分,并不能轻易减少或者删除。这时候,我们就得继续排查,为什么调用的命令,会导致CPU使用率升高或者I/O升高等问题。这些复杂案例,后面会涉及到;

最后,本案例结束时,需要清理环境:

1
docker rm -f nginx phpfpm
execsnoop

在这个案例中,我们使用了top、pidstat、pstree等工具分析了系统CPU使用率高的问题,并发现CPU升高是短时进程stress导致的,但是整个分析过程是比较复杂的。对于此类问题,有没有办法更好的监控呢?

execsnoop就是一个专为短时进程设计的工具。它通过ftrace实时监控进程的exec()行为,并输出短时进程的基本信息,包括进程ID、父进程ID、命令行参数以及执行的结果。

比如,用execsnoop监控上述案例,就可以直接得到stress进程的父进程ID以及它的命令行参数,并可以发现大量的stress进程在不停启动:

image-20230724000628868

execsnoop 所用的 ftrace 是一种常用的动态追踪技术,一般用于分析 Linux 内核的运行时行为.

小结

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

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

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