CPU性能篇：CPU使用率以及统计原理;查看CPU使用率；CPU 使用率过高的根因排查思路（锁定高消耗CPU的代码）；perf工具；案例
倪朋飞 《Linux 性能优化实战》 学习笔记
CPU使用率以及统计原理 ========================================================================================================== Linux 作为一个多任务操作系统，将每个 CPU 的时间划分为很短的时间片，再通过调度器轮流分配给各个任务使用，因此造成多任务同时运行的错觉。 为了维护 CPU 时间，Linux 通过事先定义的节拍率（内核中表示为 HZ），触发时间中断，并使用全局变量 Jiffies 记录了开机以来的节拍数。每发生一次时间中断，Jiffies 的值就加 1。 节拍率 HZ 是内核的可配选项，可以设置为 100、250、1000 等。不同的系统可能设置不同数值，你可以通过查询 /boot/config 内核选项来查看它的配置值。 grep 'CONFIG_HZ=' /boot/config-$(uname -r) Linux 通过 /proc 虚拟文件系统，向用户空间提供了系统内部状态的信息，而 /proc/stat 提供的就是系统的 CPU 和任务统计信息。 $ cat /proc/stat | grep ^cpu cpu 280580 7407 286084 172900810 83602 0 583 0 0 0 cpu0 144745 4181 176701 86423902 52076 0 301 0 0 0 cpu1 135834 3226 109383 86476907 31525 0 282 0 0 0 //man proc 然后"/proc/stat"查找说明 1.user（通常缩写为 us），代表用户态 CPU 时间。注意，它不包括下面的 nice 时间，但包括了 guest 时间。 2.nice（通常缩写为 ni），代表低优先级用户态 CPU 时间，也就是进程的 nice 值被调整为 1-19 之间时的 CPU 时间。这里注意，nice 可取值范围是 -20 到 19，数值越大，优先级反而越低。 3.system（通常缩写为 sys），代表内核态 CPU 时间。 4.idle（通常缩写为 id），代表空闲时间。注意，它不包括等待 I/O 的时间（iowait）。 5.iowait（通常缩写为 wa），代表等待 I/O 的 CPU 时间。 6.irq（通常缩写为 hi），代表处理硬中断的 CPU 时间。 7.softirq（通常缩写为 si），代表处理软中断的 CPU 时间。 8.steal（通常缩写为 st），代表当系统运行在虚拟机中的时候，被其他虚拟机占用的 CPU 时间。 9.guest（通常缩写为 guest），代表通过虚拟化运行其他操作系统的时间，也就是运行虚拟机的 CPU 时间。 10.guest_nice（通常缩写为 gnice），代表以低优先级运行虚拟机的时间。 CPU使用率统计原理 CPU 使用率=除了空闲时间外的其他时间占总 CPU 时间的百分比 注意：/proc/stat显示的是累计时间，直接查看意义不是很大 系统CPU使用率= 1 - （空闲时间new - 空闲时间old）/（总cpu时间new = 总cpu时间old） 类似的，进程的cpu数据保存在/proc/[pid]/stat中
查看 CPU 使用率 ========================================================================================================== top 显示了系统总体的 CPU 和内存使用情况，以及各个进程的资源使用情况。 ps 则只显示了每个进程的资源使用情况。 top 和 ps 这两个工具报告的 CPU 使用率，默认的结果很可能不一样： ###top 默认使用 3 秒时间间隔 ###ps 使用的却是进程的整个生命周期。 top - 10:33:27 up 11:17, 4 users, load average: 0.00, 0.01, 0.05 Tasks: 185 total, 1 running, 184 sleeping, 0 stopped, 0 zombie %Cpu0 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st #参数说明详见本节总结《CPU使用率以及统计原理》 %Cpu1 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st #默认显示所有cpu的总数据，'按键1'切换为每个 CPU 的使用率 KiB Mem : 10054452 total, 8574028 free, 777312 used, 703112 buff/cache KiB Swap: 2088956 total, 2088956 free, 0 used. 8986804 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 1 root 20 0 128404 7076 4220 S 0.0 0.1 0:02.50 systemd #%CPU 列，表示进程的 CPU 使用率。***它是用户态和内核态 CPU 使用率的总和*** 2 root 20 0 0 0 0 S 0.0 0.0 0:00.04 kthreadd #包括进程用户空间使用的 CPU、通过系统调用执行的内核空间 CPU 、以及在就绪队列等待运行的 CPU。 4 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/0:0H #在虚拟化环境中，它还包括了运行虚拟机占用的 CPU。 6 root 20 0 0 0 0 S 0.0 0.0 0:02.02 ksoftirqd/0 7 root rt 0 0 0 0 S 0.0 0.0 0:00.20 migration/0 8 root 20 0 0 0 0 S 0.0 0.0 0:00.00 rcu_bh 9 root 20 0 0 0 0 S 0.0 0.0 0:02.26 rcu_sched 10 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 lru-add-drain 11 root rt 0 0 0 0 S 0.0 0.0 0:00.16 watchdog/0 -------------------------------------------------------------------------------------------- [root@yefeng ~]# pidstat 1 5 Linux 3.10.0-1160.el7.x86_64 (yefeng) 05/29/2022 _x86_64_ (2 CPU) 10:38:45 AM UID PID %usr %system %guest %CPU CPU Command 10:38:46 AM 0 418 0.00 1.00 0.00 1.00 0 xfsaild/dm-0 10:38:46 AM 0 32270 0.00 1.00 0.00 1.00 1 pidstat ... Average: UID PID %usr %system %guest %CPU CPU Command #pidstat版本过低的关系，没有显示"%wait" Average: 0 418 0.00 0.20 0.00 0.20 - xfsaild/dm-0 Average: 0 30732 0.00 0.20 0.00 0.20 - sshd Average: 0 32270 0.20 0.80 0.00 1.00 - pidstat $ pidstat 1 5 15:56:02 UID PID %usr %system %guest %wait %CPU CPU Command 15:56:03 0 15006 0.00 0.99 0.00 0.00 0.99 1 dockerd ... Average: UID PID %usr %system %guest %wait %CPU CPU Command Average: 0 15006 0.00 0.99 0.00 0.00 0.99 - dockerd 用户态 CPU 使用率 （%usr）； 内核态 CPU 使用率（%system）； 运行虚拟机 CPU 使用率（%guest）； 等待 CPU 使用率（%wait）； 以及总的 CPU 使用率（%CPU）。
CPU 使用率过高的根因排查思路（锁定高消耗CPU的代码）；perf工具 ========================================================================================================== CPU 使用率过高的排查思路： 通过 top、ps、pidstat 等工具，你能够轻松找到 CPU 使用率较高（比如 100% ）的进程。 占用 CPU 的到底是代码里的哪个函数？ 1.GDB（The GNU Project Debugger）， 这个功能强大的程序调试利器；但是GDB 并不适合在性能分析的早期应用，因为 GDB 调试程序的过程会中断程序运行，这在线上环境往往是不允许的。 2.推荐 perf。perf 是 Linux 2.6.31 以后内置的性能分析工具。它以性能事件采样为基础，不仅可以分析系统的各种事件和内核性能，还可以用来分析指定应用程序的性能问题。 ----------------------------------------------------------------------------------------- perf top，类似于 top，它能够实时显示占用 CPU 时钟最多的函数或者指令，因此可以用来查找热点函数 perf record 和 perf report。 perf top 虽然实时展示了系统的性能信息，但它的缺点是并不保存数据，也就无法用于离线或者后续的分析。 而 perf record 则提供了保存数据的功能，保存后的数据，需要你用 perf report 解析展示。 $ perf top Samples: 833 of event 'cpu-clock', Event count (approx.): 97742399 #第一行包含三个数据，分别是采样数（Samples）、事件类型（event）和事件总数量（Event count）。 Overhead Shared Object Symbol #比如这个例子中，perf 总共采集了 833 个 CPU 时钟事件，而总事件数则为 97742399 #采样数需要我们特别注意。如果采样数过少（比如只有十几个），那下面的排序和百分比就没什么实际参考价值了。 7.28% perf [.] 0x00000000001f78a4 4.72% [kernel] [k] vsnprintf 4.32% [kernel] [k] module_get_kallsym 3.65% [kernel] [k] _raw_spin_unlock_irqrestore ... 第一列 Overhead ，是该符号的性能事件在所有采样中的比例，用百分比来表示。 第二列 Shared ，是该函数或指令所在的动态共享对象（Dynamic Shared Object），如内核、进程名、动态链接库名、内核模块名等。 第三列 Object ，是动态共享对象的类型。比如 [.] 表示用户空间的可执行程序、或者动态链接库，而 [k] 则表示内核空间。 最后一列 Symbol 是符号名，也就是函数名。#####当函数名未知时，用十六进制的地址来表示。##### 在实际使用中，我们还经常为 perf top 和 perf record 加上 -g 参数，开启调用关系的采样，方便我们根据调用链来分析性能问题。
CPU 使用率小结： ======================================================================================= CPU 使用率是最直观和最常用的系统性能指标，更是我们在排查性能问题时，通常会关注的第一个指标。 所以我们更要熟悉它的含义，尤其要弄清楚用户（%user）、Nice（%nice）、系统（%system） 、等待 I/O（%iowait） 、中断（%irq）以及软中断（%softirq）这几种不同 CPU 的使用率。比如说： 1.用户 CPU 和 Nice CPU 高，说明用户态进程占用了较多的 CPU，所以应该着重排查进程的性能问题。 2.系统 CPU 高，说明内核态占用了较多的 CPU，所以应该着重排查内核线程或者系统调用的性能问题。 3.I/O 等待 CPU 高，说明等待 I/O 的时间比较长，所以应该着重排查系统存储是不是出现了 I/O 问题。 4.软中断和硬中断高，说明软中断或硬中断的处理程序占用了较多的 CPU，所以应该着重排查内核中的中断服务程序。 碰到 CPU 使用率升高的问题，你可以借助 top、pidstat 等工具，确认引发 CPU 性能问题的来源；再使用 perf 等工具，排查出引起性能问题的具体函数。
"CPU使用率高，但top命令无法找到CPU高使用率进程"的分析；execsnoop工具 ============================================================================================================================ 通过top观察CPU使用率很高，但是看下面的进程的CPU使用率好像很正常，通过pidstat命令查看cpu也很正常。但通过top查看task数量不正常，处于R状态的进程是可疑点。 首先要想到可能是短时间的应用导致的问题，如下面的两个： （1）应用里直接调用了其他二进制程序，这些程序通常运行时间比较短，通过top等工具发现不了 （2）应用本身在不停地崩溃重启，而启动过程的资源初始化，很可能会占用很多CPU资源 碰到常规问题无法解释的 CPU 使用率情况时，首先要想到有可能是短时应用导致的问题，比如有可能是下面这两种情况。 第一，应用里直接调用了其他二进制程序，这些程序通常运行时间比较短，通过 top 等工具也不容易发现。 第二，应用本身在不停地崩溃重启，而启动过程的资源初始化，很可能会占用相当多的 CPU。 对于这类进程，我们可以用 pstree 或者 execsnoop 找到它们的父进程，再从父进程所在的应用入手，排查问题的根源。 ========================================================================================================== 也可以通过这种方式发现stress问题 用for循环输出所有running状态的进程，然后进行排序，或许就能发现问题进程了。。。 for i in `seq 1 100`;do ps aux |awk '$8 ~/R/{print $0}' >> 1234.txt;sleep 1;done for i in `seq 1 100`;do ps -eo ppid,pid,tid,class,rtprio,ni,pri,psr,pcpu,stat,comm |awk '$10 ~/R/{print $0}' >> 1234.txt;sleep 1;done for i in `seq 1 100`;do ps -eo ppid,pid,tid,class,rtprio,ni,pri,psr,pcpu,stat,comm |awk '$10 ~/R/{print $0}' ;sleep 1;done cat 1234.txt |awk '{print $11}' |sort |uniq -c pstree | grep stress execsnoop 就是一个专为短时进程设计的工具。它通过 ftrace 实时监控进程的 exec() 行为，并输出短时进程的基本信息，包括进程 PID、父进程 PID、命令行参数以及执行的结果。 用 execsnoop 监控上述案例，就可以直接得到 stress 进程的父进程 PID 以及它的命令行参数，并可以发现大量的 stress 进程在不停启动： [root@yefeng ~]# ./execsnoop Tracing exec()s. Ctrl-C to end. Instrumenting sys_execve PID PPID ARGS 120003 119982 gawk -v o=1 -v opt_name=0 -v name= -v opt_duration=0 [...] 120004 120002 cat -v trace_pipe 120001 0 <...>-120001 [001] d... 22601.215825: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 120005 74993 <...>-120005 [000] d... 22601.216984: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 120006 74998 <...>-120006 [000] d... 22601.217760: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 120007 120001 /usr/local/bin/stress -t 1 -d 1 120008 120005 /usr/local/bin/stress -t 1 -d 1 120009 120006 /usr/local/bin/stress -t 1 -d 1 120000 0 <...>-120000 [000] d... 22601.221735: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 120013 120000 /usr/local/bin/stress -t 1 -d 1 120014 74986 <...>-120014 [000] d... 22601.234865: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 120016 120014 /usr/local/bin/stress -t 1 -d 1 120019 74993 <...>-120019 [000] d... 22601.238491: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 120017 75007 <...>-120017 [001] d... 22601.241090: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 120021 120017 /usr/local/bin/stress -t 1 -d 1 120020 120019 /usr/local/bin/stress -t 1 -d 1 120024 74998 <...>-120024 [001] d... 22601.253951: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 120027 74986 <...>-120027 [001] d... 22601.257305: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 120028 120027 /usr/local/bin/stress -t 1 -d 1 120026 74978 <...>-120026 [001] d... 22601.258705: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 120030 120026 /usr/local/bin/stress -t 1 -d 1 120025 120024 /usr/local/bin/stress -t 1 -d 1 120033 74986 <...>-120033 [000] d... 22601.275611: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 120035 120033 /usr/local/bin/stress -t 1 -d 1 120034 75007 <...>-120034 [001] d... 22601.278328: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 120037 120034 /usr/local/bin/stress -t 1 -d 1 120039 74993 <...>-120039 [000] d... 22601.281742: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 120040 120039 /usr/local/bin/stress -t 1 -d 1 120041 74986 <...>-120041 [001] d... 22601.290180: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 120044 74998 <...>-120044 [000] d... 22601.292012: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 120045 120044 /usr/local/bin/stress -t 1 -d 1 120046 120041 /usr/local/bin/stress -t 1 -d 1 120043 74978 <...>-120043 [001] d... 22601.293538: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 120048 120043 /usr/local/bin/stress -t 1 -d 1 120051 75007 <...>-120051 [000] d... 22601.296635: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 120052 120051 /usr/local/bin/stress -t 1 -d 1 120054 74993 <...>-120054 [001] d... 22601.314035: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 120053 74998 <...>-120053 [001] d... 22601.315188: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 120056 120054 /usr/local/bin/stress -t 1 -d 1 120057 74986 <...>-120057 [001] d... 22601.316863: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 120058 120057 /usr/local/bin/stress -t 1 -d 1 120059 120053 /usr/local/bin/stress -t 1 -d 1 120062 74978 <...>-120062 [001] d... 22601.327741: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 120064 120062 /usr/local/bin/stress -t 1 -d 1 120066 75007 <...>-120066 [001] d... 22601.330930: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 120067 120066 /usr/local/bin/stress -t 1 -d 1 120071 74986 <...>-120071 [000] d... 22601.347464: execsnoop_sys_execve: (SyS_execve+0x0/0x30)
案例1 ========================================================================================================== 两台虚拟机，1台客户端，1台服务端 服务端运行容器： docker run --name nginx -p 10000:80 -itd feisky/nginx docker run --name phpfpm -itd --network container:nginx feisky/php-fpm 客户端开启测试： curl http://192.168.1.150:10000/ #确认服务端工作正常 ab -c 10 -n 100 http://192.168.1.150:10000/ #发起100个请求，测试实验效果 ab -c 10 -n 10000 http://192.168.1.150:10000/ #发起10000个请求,这样才有足够的排查时间。。。 排查过程： top perf top -g -p 2942 #-g开启调用关系分析，-p指定php-fpm的进程号2942 perf record -g -p 2942 #在当前目录下生成perf.data文件 docker cp perf.data phpfpm:/tmp #将perf.data文件复制到容器中 docker exec -i -t phpfpm bash #进入容器 cd /tmp/ apt-get update && apt-get install -y linux-perf linux-tools procps perf_4.9 report #注意：最后运行的工具名字是容器内部安装的版本 perf_4.9，而不是 perf 命令，这是因为 perf 会去跟内核的版本进行匹配，但镜像里面安装的perf版本有可能跟虚拟机的内核版本不一致。 ------------------------------------------------------------------------------- 排查过程： cpu使用率高的根因：程序存在问题，某一段代码大量使用了sqrt() 函数进行计算，使得用户态CPU跑满了。。。 [root@yefeng ~]# ab -c 10 -n 100 http://192.168.1.150:10000/ This is ApacheBench, Version 2.3 <$Revision: 1430300 $> Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/ Licensed to The Apache Software Foundation, http://www.apache.org/ Benchmarking 192.168.1.150 (be patient).....done Server Software: nginx/1.15.4 Server Hostname: 192.168.1.150 Server Port: 10000 Document Path: / Document Length: 9 bytes Concurrency Level: 10 Time taken for tests: 4.147 seconds Complete requests: 100 Failed requests: 0 Write errors: 0 Total transferred: 17200 bytes HTML transferred: 900 bytes Requests per second: 24.11 [#/sec] (mean) ####Nginx 承受的每秒平均请求数只有 24.11 Time per request: 414.711 [ms] (mean) Time per request: 41.471 [ms] (mean, across all concurrent requests) Transfer rate: 4.05 [Kbytes/sec] received Connection Times (ms) min mean[+/-sd] median max Connect: 0 0 0.1 0 1 Processing: 80 394 82.9 396 557 Waiting: 80 394 82.9 396 557 Total: 80 394 82.9 396 557 Percentage of the requests served within a certain time (ms) 50% 396 66% 440 75% 450 80% 456 90% 474 95% 528 98% 557 99% 557 100% 557 (longest request) ----------------------------------------------------------- 服务端开始排查 top - 10:56:34 up 38 min, 1 user, load average: 0.91, 0.21, 0.09 #进入top界面后，按下"按键1" Tasks: 185 total, 6 running, 179 sleeping, 0 stopped, 0 zombie %Cpu0 : 99.0 us, 0.3 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.7 si, 0.0 st #2个cpu的用户态 CPU 时间几乎占满了 %Cpu1 : 99.7 us, 0.0 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.3 si, 0.0 st KiB Mem : 10054452 total, 8742068 free, 801068 used, 511316 buff/cache KiB Swap: 2088956 total, 2088956 free, 0 used. 8965728 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 2942 bin 20 0 336684 9368 1688 R 45.8 0.1 0:05.23 php-fpm #几个 php-fpm 进程的 CPU 使用率加起来接近 200% 2946 bin 20 0 336684 9360 1680 R 42.5 0.1 0:04.18 php-fpm #确认是用户空间的 php-fpm 进程，导致 CPU 使用率骤升。 2943 bin 20 0 336684 9364 1684 R 38.9 0.1 0:05.11 php-fpm 2944 bin 20 0 336684 9360 1680 R 35.5 0.1 0:03.96 php-fpm 2945 bin 20 0 336684 9360 1680 R 34.6 0.1 0:04.30 php-fpm 2855 101 20 0 33092 2156 776 S 1.0 0.0 0:00.16 nginx 504 root 20 0 39308 4932 4420 S 0.7 0.0 0:00.36 systemd-journal 2259 root 20 0 736872 31120 14688 S 0.7 0.3 0:01.92 dockerd-current 14 root 20 0 0 0 0 S 0.3 0.0 0:00.05 ksoftirqd/1 761 root 20 0 295380 5224 3960 S 0.3 0.1 0:01.64 vmtoolsd 2811 root 20 0 339844 4996 1652 S 0.3 0.0 0:00.04 docker-containe 2925 root 20 0 0 0 0 S 0.3 0.0 0:00.12 kworker/0:1 2947 root 20 0 164300 2412 1616 R 0.3 0.0 0:00.04 top 1 root 20 0 128580 7212 4244 S 0.0 0.1 0:02.14 systemd 2 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kthreadd 4 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/0:0H 6 root 20 0 0 0 0 S 0.0 0.0 0:00.03 ksoftirqd/0 perf top -g -p 2942 #-g开启调用关系分析，-p指定php-fpm的进程号2942 Samples: 1K of event 'cpu-clock', 4000 Hz, Event count (approx.): 332000000 lost: 0/0 drop: 0/0 Children Self Shared Object Symbol + 99.92% 0.00% [unknown] [.] 0x6cb6258d4c544155 + 99.92% 0.00% libc-2.24.so [.] 0x00007fd16ef262e1 - 99.40% 0.00% php-fpm [.] 0x000055642eacc642 #按方向键切换到 php-fpm，再按下回车键展开 php-fpm 的调用关系，你会发现，调用关系最终到了 sqrt 和 add_function。 0x55642eacc642 #实际查看结果为16进制数字（因为当函数名未知时，用十六进制的地址来表示） 0x55642e87d6fc #原因为perf无法找到待分析进程所依赖的库 0x55642e92cf94 #这个问题其实是在分析Docker容器应用时经常会碰到的一个问题，因为容器应用所依赖的库都在镜像里面。 - 0x55642e9c4323 + 93.00% 0x55642e9c396e 1.73% 0x55642e9c397a 1.13% 0x55642e9c3971 0.75% 0x55642e9c3966 + 99.40% 0.00% php-fpm [.] 0x000055642e87d6fc + 99.40% 0.00% php-fpm [.] 0x000055642e92cf94 + 99.40% 0.00% php-fpm [.] 0x000055642e9c4323 + 93.00% 0.00% php-fpm [.] 0x000055642e9c396e + 20.11% 0.00% php-fpm [.] 0x000055642e9c5a7c + 16.11% 0.00% php-fpm [.] 0x000055642ea8eea3 + 5.35% 5.35% libm-2.24.so [.] 0x000000000002127e + 5.35% 0.00% libm-2.24.so [.] 0x00007fd172fce27e 两个解决思路： （1）在容器外面构建相同路径的依赖库。这种方法不推荐，一是因为找出这些依赖比较麻烦，更重要的是构建这些路径会污染虚拟机的环境。 （2）在容器外面把分析纪录保存下来，到容器里面再去查看结果，这样库和符号的路径就都是对的了。 perf record -g -p 2942 #在当前目录下生成perf.data文件 docker cp perf.data phpfpm:/tmp #将perf.data文件复制到容器中 docker exec -i -t phpfpm bash #进入容器 cd /tmp/ apt-get update && apt-get install -y linux-perf linux-tools procps perf_4.9 report #注意：最后运行的工具名字是容器内部安装的版本 perf_4.9，而不是 perf 命令，这是因为 perf 会去跟内核的版本进行匹配，但镜像里面安装的perf版本有可能跟虚拟机的内核版本不一致。 Samples: 31K of event 'cpu-clock', Event count (approx.): 7809250000 Children Self Command Shared Object Symbol - 99.96% 0.00% php-fpm libc-2.24.so [.] __libc_start_main - __libc_start_main - 99.55% 0x9cb642 - 99.54% php_execute_script - 99.50% zend_execute_scripts - 99.46% zend_execute - 96.62% execute_ex - 18.71% 0x8c4a7c 5.30% sqrt #调用关系最终到了 sqrt 和 add_function。看来，我们需要从这两个函数入手了。 0.67% 0x681d1a 0.59% 0x681d21 - 15.56% 0x98dea3 - 3.23% 0x98dd97 add_function #调用关系最终到了 sqrt 和 add_function。看来，我们需要从这两个函数入手了。 1.39% 0x98de23 0.66% add_function 0.52% 0x98dd9e 3.73% 0x94ede0 2.24% 0x8c4a6c 2.05% 0x9513cc 1.95% 0x8c4ae5 $ docker cp phpfpm:/app . # 从容器phpfpm中将PHP源码拷贝出来 $ grep sqrt -r app/ #使用grep查找函数调用,找到了sqrt调用 app/index.php: $x += sqrt($x); $ grep add_function -r app/ #没找到add_function调用，这其实是PHP内置函数 [root@yefeng ~]# cat app/index.php #查看调用sqrt函数的源文件 <?php // test only. $x = 0.0001; for ($i = 0; $i <= 1000000; $i++) { #nginx并发低的原因，被这个循环占用了大量的cpu资源 $x += sqrt($x); } echo "It works!" ------------------------------------------------------------------------------------- 服务端修复 # 停止原来的应用 $ docker rm -f nginx phpfpm # 运行优化后的应用 $ docker run --name nginx -p 10000:80 -itd feisky/nginx:cpu-fix $ docker run --name phpfpm -itd --network container:nginx feisky/php-fpm:cpu-f #下载新的镜像失败；进入phpfpm容器直接删除index.php文件内的for循环 [root@yefeng ~]# ab -c 10 -n 10000 http://192.168.1.150:10000/ This is ApacheBench, Version 2.3 <$Revision: 1430300 $> Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/ Licensed to The Apache Software Foundation, http://www.apache.org/ Benchmarking 192.168.1.150 (be patient) Completed 1000 requests …… Finished 10000 requests Server Software: nginx/1.15.4 Server Hostname: 192.168.1.150 Server Port: 10000 Document Path: / Document Length: 9 bytes Concurrency Level: 10 Time taken for tests: 3.550 seconds Complete requests: 10000 Failed requests: 0 Write errors: 0 Total transferred: 1720000 bytes HTML transferred: 90000 bytes Requests per second: 2817.01 [#/sec] (mean) #Nginx 承受的每秒平均请求数从24提升为2817 Time per request: 3.550 [ms] (mean) Time per request: 0.355 [ms] (mean, across all concurrent requests) Transfer rate: 473.17 [Kbytes/sec] received Connection Times (ms) min mean[+/-sd] median max Connect: 0 0 0.4 0 21 Processing: 1 3 1.9 3 27 Waiting: 1 3 1.8 3 27 Total: 1 4 1.9 3 28 Percentage of the requests served within a certain time (ms) 50% 3 66% 4 75% 4 80% 4 90% 5 95% 6 98% 8 99% 11 100% 28 (longest request)
案例2 ========================================================================================================== 两台虚拟机，1台客户端，1台服务端 服务端运行容器： docker run --name nginx -p 10000:80 -itd feisky/nginx:sp docker run --name phpfpm -itd --network container:nginx feisky/php-fpm:sp 客户端开启测试： curl http://192.168.1.150:10000/ #确认服务端工作正常 ab -c 100 -n 1000 http://192.168.1.150:10000/ #并发100个请求测试Nginx性能，总共测试1000个请求 ab -c 5 -t 600 http://192.168.1.150:10000/ #将测试的并发请求数改成 5，同时把请求时长设置为 10 分钟 排查命令 top pidstat 1 top -o S pidstat -p 14442 ps aux | grep 14442 pstree | grep stress grep stress -r app #app是一个目录 ----------------------------------------------------------------------------- 确认问题 [root@yefeng ~]# ab -c 100 -n 1000 http://192.168.1.150:10000/ …… Concurrency Level: 100 Time taken for tests: 5.772 seconds Complete requests: 1000 Failed requests: 0 Write errors: 0 Total transferred: 172000 bytes HTML transferred: 9000 bytes Requests per second: 173.24 [#/sec] (mean) ######Nginx 能承受的每秒平均请求数，只有 173多一点 Time per request: 577.242 [ms] (mean) Time per request: 5.772 [ms] (mean, across all concurrent requests) Transfer rate: 29.10 [Kbytes/sec] received ab -c 5 -t 600 http://192.168.1.150:10000/ #将测试的并发请求数改成 5，同时把请求时长设置为 10 分钟 ----------------------------------------------------------------------------- 排查分析过程 top显示cpu使用率很高，但找不到相关进程的根因：应用里直接调用了其他二进制程序，这些程序通常运行时间比较短，通过top等工具发现不了 top - 15:44:55 up 5:27, 2 users, load average: 2.14, 2.61, 3.36 #top命令默认以CPU进行排序 Tasks: 196 total, 6 running, 190 sleeping, 0 stopped, 0 zombie %Cpu0 : 66.9 us, 22.3 sy, 0.0 ni, 8.1 id, 0.0 wa, 0.0 hi, 2.7 si, 0.0 st #可以发现2个CPU的使用率都比较高 %Cpu1 : 66.4 us, 23.8 sy, 0.0 ni, 4.4 id, 0.0 wa, 0.0 hi, 5.4 si, 0.0 st #系统的整体 CPU 使用率是比较高的：用户 CPU 使用率（us）已经到了 66%，系统 CPU 为 23%，而空闲 CPU （id）则只有 4.4%。 KiB Mem : 10054452 total, 7695996 free, 881544 used, 1476912 buff/cache KiB Swap: 2088956 total, 2088956 free, 0 used. 8584384 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 5378 101 20 0 33092 2192 772 R 6.3 0.0 3:53.09 nginx #但是CPU 使用率最高的进程也只不过才 6.3%，看起来并不高。 126541 bin 20 0 336684 9588 1912 S 3.3 0.1 0:00.69 php-fpm #Nginx 和 php-fpm 是运行 Web 服务的，它们会占用一些 CPU 也不意外，并且 6% 的 CPU 使用率也不算高 126558 bin 20 0 336684 9576 1900 S 3.3 0.1 0:00.68 php-fpm 126567 bin 20 0 336684 9580 1904 S 3.3 0.1 0:00.68 php-fpm 126546 bin 20 0 336684 9588 1912 S 3.0 0.1 0:00.69 php-fpm 126553 bin 20 0 336684 9576 1900 S 3.0 0.1 0:00.68 php-fpm 504 root 20 0 133696 74496 73984 S 2.0 0.7 2:23.96 systemd-journal 2259 root 20 0 885304 44888 16440 S 1.7 0.4 1:18.16 dockerd-current #后面的进程CPU 使用率更低，看起来不太像会导致用户 CPU 使用率达到 66%。 5334 root 20 0 341252 5012 1652 S 1.3 0.0 0:46.48 docker-containe ……………………………… 6 root 20 0 0 0 0 S 0.0 0.0 0:03.22 ksoftirqd/0 7 root rt 0 0 0 0 S 0.0 0.0 0:00.93 migration/0 8 root 20 0 0 0 0 S 0.0 0.0 0:00.00 rcu_bh 9 root 20 0 0 0 0 R 0.0 0.0 0:09.69 rcu_sched 10 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 lru-add-drain 11 root rt 0 0 0 0 S 0.0 0.0 0:00.06 watchdog/0 [root@yefeng ~]# pidstat 1 #间隔1秒输出一组数据（按Ctrl+C结束） Linux 3.10.0-1160.el7.x86_64 (yefeng) 05/29/2022 _x86_64_ (2 CPU) 03:52:19 PM UID PID %usr %system %guest %CPU CPU Command 03:52:20 PM 0 504 2.97 2.97 0.00 5.94 1 systemd-journal #pidstat命令也失效了，CPU使用率加起来也不高 03:52:20 PM 0 1133 0.00 0.99 0.00 0.99 1 rsyslogd 03:52:20 PM 0 2259 0.00 0.99 0.00 0.99 0 dockerd-current 03:52:20 PM 0 2265 0.00 0.99 0.00 0.99 0 docker-containe 03:52:20 PM 0 5334 0.00 0.99 0.00 0.99 1 docker-containe 03:52:20 PM 101 5378 0.00 4.95 0.00 4.95 0 nginx 03:52:20 PM 1 15738 0.99 2.97 0.00 3.96 0 php-fpm 03:52:20 PM 1 15746 0.00 2.97 0.00 2.97 0 php-fpm 03:52:20 PM 1 15755 0.99 3.96 0.00 4.95 1 php-fpm 03:52:20 PM 1 15757 0.00 4.95 0.00 4.95 0 php-fpm 03:52:20 PM 1 15767 0.00 2.97 0.00 2.97 0 php-fpm 03:52:20 PM 0 17700 0.00 0.99 0.00 0.99 1 pidstat top -o S #使用指定列（指定列名）进行排查，进入后按R进行sort top 命令使用教程 https://blog.csdn.net/qq_19922839/article/details/120011790 top - 15:56:23 up 5:38, 2 users, load average: 5.81, 4.73, 4.11 Tasks: 199 total, 9 running, 189 sleeping, 0 stopped, 1 zombie #这里存在遗漏信息：平均负载很高，Running 状态的进程有点多 %Cpu(s): 64.6 us, 23.5 sy, 0.0 ni, 7.8 id, 0.0 wa, 0.0 hi, 4.1 si, 0.0 st KiB Mem : 10054452 total, 7599556 free, 901728 used, 1553168 buff/cache KiB Swap: 2088956 total, 2088956 free, 0 used. 8542316 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 9 root 20 0 0 0 0 R 0.3 0.0 0:10.89 rcu_sched 5422 root 20 0 336300 35156 27756 R 0.0 0.3 0:11.15 php-fpm 14436 bin 20 0 7272 428 344 R 0.0 0.0 0:00.00 stress #感觉stress有些奇怪，所以进行进一步分析 14442 bin 20 0 8172 600 104 R 0.0 0.0 0:00.00 stress #pidstat命令、ps命令均无法输出该进程的相关信息（因为这个进程已经没了！） 14443 bin 20 0 8180 1120 104 R 0.0 0.0 0:00.00 stress #重新观察，发现stress的进程ID一直在变化 14444 bin 20 0 336684 7676 0 R 0.0 0.1 0:00.00 php-fpm 15738 bin 20 0 336684 9588 1912 R 3.3 0.1 0:08.30 php-fpm 15755 bin 20 0 336684 9576 1900 R 4.0 0.1 0:08.10 php-fpm 87967 root 20 0 164312 2444 1624 R 0.0 0.0 0:00.14 top 1 root 20 0 128580 7212 4244 S 0.0 0.1 0:02.70 systemd 2 root 20 0 0 0 0 S 0.0 0.0 0:00.02 kthreadd 4 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/0:0H 6 root 20 0 0 0 0 S 0.3 0.0 0:03.72 ksoftirqd/0 7 root rt 0 0 0 0 S 0.0 0.0 0:01.05 migration/0 8 root 20 0 0 0 0 S 0.0 0.0 0:00.00 rcu_bh 10 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 lru-add-drain 11 root rt 0 0 0 0 S 0.0 0.0 0:00.06 watchdog/0 12 root rt 0 0 0 0 S 0.0 0.0 0:00.05 watchdog/1 [root@yefeng ~]# pidstat -p 14442 #查看指定进程，发现无输出（因为这个进程已经没了！） Linux 3.10.0-1160.el7.x86_64 (yefeng) 05/29/2022 _x86_64_ (2 CPU) 03:59:10 PM UID PID %usr %system %guest %CPU CPU Command [root@yefeng ~]# ps aux | grep 14442 #ps命令查看该进程，也没有输出（因为这个进程已经没了！） ###进程的 PID 在变，无非也就两个原因 第一个原因，进程在不停地崩溃重启，比如因为段错误、配置错误等等，这时，进程在退出后可能又被监控系统自动重启了。 第二个原因，这些进程都是短时进程，也就是在其他应用内部通过 exec 调用的外面命令。这些命令一般都只运行很短的时间就会结束，你很难用 top 这种间隔时间比较长的工具发现（上面的案例，我们碰巧发现了）。 stress，我们前面提到过，它是一个常用的压力测试工具。它的 PID 在不断变化中，看起来像是被其他进程调用的短时进程。要想继续分析下去，还得找到它们的父进程。 [root@yefeng ~]# pstree | grep stress #stress 是被 php-fpm 调用的子进程，并且进程数量不止一个 | | |-docker-containe-+-php-fpm-+-4*[php-fpm---sh---stress---stress] [root@yefeng ~]# docker ps #php-fpm是在phpfpm容器中被调用 CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES 7a2735a8986f feisky/php-fpm:sp "php-fpm -F --pid ..." 2 hours ago Up 2 hours phpfpm 944341a9c1a1 feisky/nginx:sp "nginx -g 'daemon ..." 2 hours ago Up 2 hours 0.0.0.0:10000->80/tcp nginx 查看源码 [root@yefeng ~]# docker cp phpfpm:/app . # 拷贝源码到本地 [root@yefeng ~]# grep stress -r app # grep 查找看看是不是有代码在调用stress命令 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); [root@yefeng ~]# cat app/index.php #查看源码 <?php // fake I/O with stress (via write()/unlink()). #从注释上看，stress 会通过 write() 和 unlink() 对 I/O 进程进行压测，看来，这应该就是系统 CPU 使用率升高的根源了 $result = exec("/usr/local/bin/stress -t 1 -d 1 2>&1", $output, $status); if (isset($_GET["verbose"]) && $_GET["verbose"]==1 && $status != 0) { #stress 模拟的是 I/O 压力，而之前在 top 的输出中看到的，却一直是用户 CPU 和系统 CPU 升高，并没见到 iowait 升高。 echo "Server internal error: "; print_r($output); } else { echo "It works!"; } ?> [root@yefeng ~]# curl http://192.168.1.150:10000/?verbose=1 Server internal error: Array ( [0] => stress: info: [41611] dispatching hogs: 0 cpu, 0 io, 0 vm, 1 hdd [1] => stress: FAIL: [41612] (563) mkstemp failed: Permission denied ###错误信息 [2] => stress: FAIL: [41611] (394) <-- worker 41612 returned error 1 [3] => stress: WARN: [41611] (396) now reaping child worker processes [4] => stress: FAIL: [41611] (400) kill error: No such process [5] => stress: FAIL: [41611] (451) failed run completed in 0s ###错误信息 ) #我们发现了一个 PHP 调用外部 stress 命令的 bug：没有权限创建临时文件。 [root@yefeng ~]# perf record -g [root@yefeng ~]# perf report
【推荐】国内首个AI IDE，深度理解中文开发场景，立即下载体验Trae
【推荐】编程新体验，更懂你的AI，立即体验豆包MarsCode编程助手
【推荐】抖音旗下AI助手豆包，你的智能百科全书，全免费不限次数
【推荐】轻量又高性能的 SSH 工具 IShell：AI 加持，快人一步
· 阿里最新开源QwQ-32B，效果媲美deepseek-r1满血版，部署成本又又又降低了！
· 单线程的Redis速度为什么快？
· SQL Server 2025 AI相关能力初探
· AI编程工具终极对决：字节Trae VS Cursor，谁才是开发者新宠？
· 展开说说关于C#中ORM框架的用法！