排查lscpu缓慢¶
我最近的一个案例：升级了服务器的内核，并且按照运行 gVisor安全容器 需求，开启了 IOMMU 相关内核参数。被升级的服务器是比较早期安装的系统，由于生产环境内核经过多次迭代，近期安装的内核版本看起来差异不大(仅小版本序号变化)，但是内核参数变化极大，而且还可能存在hotfix差异，所以我对安装软件包(kernel+hotfix)和内核参数进行了比对。
升级完内核，安装完hotfix包，并且使用 grubby修改内核参数 对内核参数差异进行订正，确保了升级后的服务器内核参数和新安装服务器完全一致，看起来应该没有问题了。
然而，我非常惊讶地发现，系统中出现了很多 lscpu 进程，每个进程都占用了 100% 的CPU资源:
top - 15:11:36 up 21:10, 1 user, load average: 144.45, 149.28, 156.12
Tasks: 2280 total, 52 running, 1584 sleeping, 0 stopped, 0 zombie
%Cpu(s): 21.2 us, 15.6 sy, 0.0 ni, 62.2 id, 0.0 wa, 0.0 hi, 1.0 si, 0.0 st
KiB Mem : 52787315+total, 37171612+free, 89773848 used, 66383168 buff/cache
KiB Swap: 0 total, 0 free, 0 used. 41481331+avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
414241 1102 20 0 4102164 1.3g 23944 S 364.9 0.3 3055:20 java
410765 1102 20 0 4080676 1.3g 24012 S 321.6 0.3 3163:08 java
457989 1102 20 0 4557836 2.3g 22604 S 313.5 0.5 776:21.89 java
...
28491 root 20 0 74308 21584 16436 S 221.6 0.0 2003:07 nydusd-rs
...
3879 root 10 -10 281092 99184 20816 S 178.4 0.0 1553:57 AliYunDun
...
65153 root 20 0 12948 2240 2004 R 100.0 0.0 0:32.59 lscpu
65229 root 20 0 12948 2044 1808 R 100.0 0.0 0:32.83 lscpu
65282 root 20 0 12948 2192 1960 R 100.0 0.0 0:31.25 lscpu
65335 root 20 0 12948 2160 1924 R 100.0 0.0 0:30.69 lscpu
65361 root 20 0 12948 2248 2012 R 100.0 0.0 0:32.58 lscpu
65696 root 20 0 12948 2300 2064 R 100.0 0.0 0:32.50 lscpu
65698 root 20 0 12948 2160 1924 R 100.0 0.0 0:30.94 lscpu
65724 root 20 0 12948 2240 2004 R 100.0 0.0 0:32.46 lscpu
对比了一下异常的服务器(内核升级后的服务器)和正常的服务器(采用装机模版安装的最新标准服务器)，异常服务器实际上 lscpu 也能执行完成，只是异常缓慢:
$time lscpu
...
real 0m5.873s
user 0m0.046s
sys 0m5.799s
$time lscpu
...
real 0m53.452s
user 0m0.033s
sys 0m52.720s
耗时从 6秒到53秒 ，时间变化幅度很大，但都异常缓慢。正常服务器只耗时 0.36秒
排查¶
使用 strace系统调用跟踪 来检查
lscpu究竟做了什么事: 可以看到 正常的主机lscpu只有2位数的read syscall，但是异常主机则高达 2w 的read syscall
$time strace -c lscpu
...
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
99.23 48.323826 19692 2454 read
0.46 0.224475 116 1939 775 access
0.21 0.101119 76 1323 mmap
0.03 0.016640 13 1327 12 open
0.03 0.015077 11 1313 munmap
0.02 0.008951 7 1318 close
0.02 0.007683 6 1316 fstat
0.00 0.000429 13 32 write
0.00 0.000045 15 3 getdents
0.00 0.000020 20 1 stat
0.00 0.000011 11 1 getuid
0.00 0.000011 11 1 openat
0.00 0.000005 5 1 lseek
0.00 0.000000 0 6 mprotect
0.00 0.000000 0 4 brk
0.00 0.000000 0 1 execve
0.00 0.000000 0 1 uname
0.00 0.000000 0 1 arch_prctl
------ ----------- ----------- --------- --------- ----------------
100.00 48.698292 11042 787 total
real 0m51.828s
user 0m0.148s
sys 0m49.882s
$time strace -c lscpu
...
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
66.07 0.101868 46 2201 read
11.27 0.017375 8 1939 1031 access
6.36 0.009810 9 1071 11 open
5.79 0.008934 8 1057 munmap
3.88 0.005983 5 1067 mmap
3.41 0.005262 4 1063 close
3.10 0.004773 4 1060 fstat
0.04 0.000057 9 6 mprotect
0.03 0.000039 13 3 getdents
0.01 0.000015 15 1 stat
0.01 0.000015 3 4 brk
0.01 0.000015 15 1 rt_sigaction
0.01 0.000010 5 2 lseek
0.01 0.000010 10 1 openat
0.01 0.000009 4 2 rt_sigprocmask
0.00 0.000005 5 1 uname
0.00 0.000005 5 1 arch_prctl
0.00 0.000004 4 1 getuid
0.00 0.000000 0 30 write
0.00 0.000000 0 1 execve
------ ----------- ----------- --------- --------- ----------------
100.00 0.154189 9512 1042 total
real 0m0.358s
user 0m0.039s
sys 0m0.344s
那么究竟是什么导致异常 lscpu 消耗了这么多 read syscall ?
再次使用
strace lscpu直接查看调用了那些syscall:time strace lscpu 2>&1 | tee strace_lscpu.log
我对比了正常服务器和异常服务器的 strace_lscpu.log ，惊讶地发现，实际上两个日志文件的行数差别并不是特别大:
# 异常服务器
$wc -l strace_lscpu.log
11045 strace_lscpu.log
# 正常服务器
$wc -l strace_lscpu.log
9507 strace_lscpu.log
而且每次生成的 strace_lscpu.log 行数完全一致。能够明显感觉到异常服务器的 strace 输出特别缓慢
使用了文件diff工具
meld对比了两个主机的strace_lscpu.log，发现了一点点差异:lscpu会尝试去读取/sys/devices/system/cpu/cpu0/cpufreq，此时异常服务器是能够读取的，而正常服务器则显示该目录文件不存在。这是一个线索:
检查发现，异常服务器多了一个 /sys/devices/system/cpu/cpuX/cpufreq ，例如:
/sys/devices/system/cpu/cpu0 目录下
lrwxrwxrwx 1 root root 0 Jul 20 16:44 cpufreq -> ../cpufreq/policy0
每个CPU核心都对应有这个 policyX 目录，包含了一下内容:
affected_cpus cpuinfo_cur_freq cpuinfo_transition_latency scaling_available_frequencies scaling_driver scaling_min_freq
bios_limit cpuinfo_max_freq freqdomain_cpus scaling_available_governors scaling_governor scaling_setspeed
cpb cpuinfo_min_freq related_cpus scaling_cur_freq scaling_max_freq
所以 lscpu 会读取这个目录下的 cpuinfo_max_freq 和 cpuinfo_min_freq 实际内容如下:
$cat cpuinfo_max_freq
2000000
$cat cpuinfo_min_freq
1200000
服务器硬件略有差异(型号和主频)，可以看到
异常服务器是:
Model name: Hygon C86 7285 32-core Processor
Stepping: 1
CPU MHz: 2456.693
CPU max MHz: 2000.0000
CPU min MHz: 1200.0000
BogoMIPS: 4000.20
Virtualization: AMD-V
正常服务器:
Model name: Hygon C86 7291 32-core Processor
Stepping: 1
CPU MHz: 2744.609
BogoMIPS: 4600.23
Virtualization: AMD-V
我发现一个异常之处，异常服务的 /sys/devices/system/cpu/cpuX/policyX/cpuinfo_max_freq (2G MHz) 实际上比 CPU MHz （2.5G MHz) 要低很多，看上去策略限制CPU主频。这点会不会导致比较特别的异常呢？
想到还有一批服务器虽然 grubby修改内核参数 调整了启动参数，但是由于没有重启，实际上尚未生效。而且未重启的服务器硬件和我这台存在异常的服务器硬件是完全一致的。我找了一台，执行:
$time lscpu ... Model name: Hygon C86 7285 32-core Processor Stepping: 1 CPU MHz: 2484.086 BogoMIPS: 3999.78 Virtualization: AMD-V ... real 0m0.106s user 0m0.010s sys 0m0.096s
可以看到同样的硬件(处理器)，在没有启用新的内核参数时， lscpu 的性能极快。并且，可以看到，相同内核但是使用旧的内核配置，CPU主频是不显示CPU policy 主频的，也就是 没有
CPU max MHz: 2000.0000
CPU min MHz: 1200.0000
所以，很大可能是存在和 CPU频率 性能伸缩(Performance Scaling) 相关的问题
对比 CPU频率 性能伸缩(Performance Scaling)¶
经过对比，基本可以确定存在异常的服务器启用了 CPU频率 性能伸缩(Performance Scaling) 功能: 那为何同样内核和内核参数，新安装的模版服务器不显示 cpu frequency scaling 的 governor ? 而我手动升级服务器却出现
检查 CPU governor:
cpupower frequency-info
可以看到:
analyzing CPU 0:
driver: acpi-cpufreq
CPUs which run at the same hardware frequency: 0
CPUs which need to have their frequency coordinated by software: 0
maximum transition latency: Cannot determine or is not supported.
hardware limits: 1.20 GHz - 2.00 GHz
available frequency steps: 2.00 GHz, 1.60 GHz, 1.20 GHz
available cpufreq governors: conservative ondemand userspace powersave performance
current policy: frequency should be within 1.20 GHz and 2.00 GHz.
The governor "performance" may decide which speed to use
within this range.
current CPU frequency: 2.00 GHz (asserted by call to hardware)
boost state support:
Supported: no
Active: no
Boost States: 0
Total States: 3
Pstate-P0: 2000MHz
Pstate-P1: 1600MHz
Pstate-P2: 1200MHz
我推测系统加载了 Scaling drivers ，但是不确定是哪种，照理说 AMD 处理器 支持 amd_pstate 需要处理器有 cppc flag，则可以传递内核参数 amd_pstate.replace=1 来激活。不过，海光的这款 7285 处理器并没有这个 cppc flag(国产化海光处理器阉割了 AMD Zen微架构 的加密和电源管理功能，或者说替换了原架构中的这部分功能，但做得极不完善 )并且我的内核参数也没有激活 amd_pstate.replace=1
在参考文档 arch linux: CPU frequency scaling 中关于 cpufreq 内核模块检查方法如下:
ls /usr/lib/modules/$(uname -r)/kernel/drivers/cpufreq/
可以看到如下内核模块:
acpi-cpufreq.ko amd_freq_sensitivity.ko p4-clockmod.ko pcc-cpufreq.ko powernow-k8.ko speedstep-lib.ko
我突然想到看看是否加载了内核模块:
lsmod | grep freq
果然看出了差异:
存在异常的(内核升级)服务器同时包含了2个 CPU频率 性能伸缩(Performance Scaling) 内核模块:
pcc_cpufreq 16384 0 acpi_cpufreq 24576 0
正常(新装机模版)服务器只有1个 CPU频率 性能伸缩(Performance Scaling) 内核模块:
pcc_cpufreq 16384 0
移除 CPU频率 性能伸缩(Performance Scaling)¶
在异常的(内核升级)服务器卸载 acpi_cpufreq 内核模块:
modprobe -r acpi_cpufreq
果然，卸载以后，原先存在的 /sys/devices/system/cpu/cpu0/cpufreq/scaling_available_governors 入口立即消失了:
#ls /sys/devices/system/cpu/cpu0/cpufreq/scaling_available_governors
ls: cannot access /sys/devices/system/cpu/cpu0/cpufreq/scaling_available_governors: No such file or directory
而且原先存在的 /sys/devices/system/cpu/cpuX/cpufreq 也消失了。有戏!
此时再次执行
time lscpu发现速度大大提高，而且原先存在CPU max MHz和CPU min MHz也消失了(因为读不到 CPU频率 性能伸缩(Performance Scaling) 的sysfs内容):$time lscpu ... Model name: Hygon C86 7285 32-core Processor Stepping: 1 CPU MHz: 2428.609 BogoMIPS: 4000.20 Virtualization: AMD-V ... real 0m0.136s user 0m0.010s sys 0m0.125s
但不是每次都这么块，也有耗时3秒或者7秒，甚至依然耗时49秒的。但是，有进展，说明 cpufreq 功能确实影响 lscpu 。 安全地清空一个Kubernetes节点 (确保该主机上无运行程序)，我重新测试了 time lscpu ，所有测试都显示响应恢复到正常水平。
正常服务器没有加载 acpi_cpufreq 原因¶
为何正常装机模版的服务器启动时候没有加载 acpi_cpufreq 内核模块？
我在正常装机模版安装的服务器上执行内核 acpi_cpufreq 内核模块加载:
sudo modprobe acpi_cpufreq
出现报错:
modprobe: ERROR: could not insert 'acpi_cpufreq': No such device
这个报错参考:
有以下条件需要满足:
BIOS中需要启用电源管理(Power Profile)，并且配置
Power Regulator为OS Control Mode，也就是电源管理调节器采用操作系统控制模式内核启动参数关闭了
intel_pstate:intel_pstate=disable
咨询了同事，海光服务器BIOS设置应该是关闭 cpufreq 支持的，也就是说应该是关闭电源管理。
对比异常服务器能够自动加载 acpi_cpufreq ，而后续新服务器自动拒绝加载 acpi_cpufreq ，说明:
早期服务器BIOS没有关闭电源管理功能，所以我按照最新装机模版服务器配置了
processor.max_cstate=0就自动加载了acpi_cpufreq模块，自动启用了 CPU频率 性能伸缩(Performance Scaling) 功能而最新模版安装的海光服务器，由于BIOS关闭电源管理功能，所以即使配置了内核参数
processor.max_cstate=0也无影响，不会加载acpi_cpufreq内核模块，也就不受海光 CPU频率 性能伸缩(Performance Scaling) 功能缺陷影响
排障¶
排除法方案:
测试一: 安全地清空一个Kubernetes节点 (确保该主机上无运行程序)，然后对比加载
acpi_cpufreq性能(同时运行 Sysbench性能测试 进行性能压力)(取消)测试二: 将异常服务器上pods迁移走，然后重启服务器，在保留
cpufreq开启情况下(即还是加载acpi_cpufreq)，测试lscpu测试三: 异常服务器配置
acpi_cpufreq内核模块加载黑名单，然后重启服务器确保 没有加载acpi_cpufreq，测试lscpu测试四(补充): 实际测试一和三都没有彻底解决
lscpu缓慢问题(测试三有改善)，但是我google到 ADM Ryzon处理器随机”冻结”问题
测试一¶
服务器 安全地清空一个Kubernetes节点 我对比加载
acpi_cpufreq:加载
acpi_cpufreq模块前后执行time lscpu结果都很快，完全没有延迟，这说明当服务器没有负载情况下不影响lscpu运行为了模拟主机压力，我执行 Sysbench性能测试 (但是很不幸，依然没有出现
lscpu延迟)sysbench cpu –cpu-max-prime=20000000 –threads=128 run
压测时候显示 top :
top - 14:43:09 up 1 day, 20:42, 4 users, load average: 112.87, 44.50, 17.59
Tasks: 1221 total, 1 running, 593 sleeping, 0 stopped, 0 zombie
%Cpu(s): 99.9 us, 0.1 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 52787315+total, 48091430+free, 12048776 used, 34910060 buff/cache
KiB Swap: 0 total, 0 free, 0 used. 49341356+avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
459519 admin 20 0 102328 7132 5228 S 12713 0.0 257:00.14 sysbench
3879 root 10 -10 295268 113360 20816 S 6.2 0.0 2523:02 AliYunDun
12960 root 20 0 8805024 105620 58904 S 4.9 0.0 404:38.87 containerd
同时不断刷新 time lscpu ，发现几乎没有延迟，最多也就1秒钟左右
我观察发现 sysbench cpu 测试完全是 user 态测试，纯计算，没有任何 sys 压力，而之前出现异常 lscpu 响应慢，是有比较大的 sys 压力。这说明系统存在大量的 system calls
警告
排查方向有误？ 既然系统有大量的 system calls ，是否需要排查来源 - lscpu 缓慢可能是因为CPU忙于处理 system call 无法响应查询？
测试三¶
异常服务器配置
acpi_cpufreq内核模块加载黑名单: 配置/etc/modprobe.d/blacklist-cpufreq.confblacklist acpi_cpufreq
重启服务器后检查:
lsmod | grep cpufreq
发现之前加载的2个 cpufreq 相关内核模块都没有加载
检查
cpupower frequency-info：
analyzing CPU 0:
no or unknown cpufreq driver is active on this CPU
CPUs which run at the same hardware frequency: Not Available
CPUs which need to have their frequency coordinated by software: Not Available
maximum transition latency: Cannot determine or is not supported.
Not Available
available cpufreq governors: Not Available
Unable to determine current policy
current CPU frequency: Unable to call hardware
current CPU frequency: Unable to call to kernel
boost state support:
Supported: no
Active: no
Boost States: 0
Total States: 3
Pstate-P0: 2000MHz
Pstate-P1: 1600MHz
Pstate-P2: 1200MHz
检查CPU核心主频:
sudo cpupower monitor
现在输出类似:
| Mperf
PKG|CORE| CPU| C0 | Cx | Freq
0| 0| 0| 39.86| 60.14| 2450
0| 0| 64| 39.09| 60.91| 2452
0| 1| 1| 42.94| 57.06| 2466
0| 1| 65| 39.03| 60.97| 2467
0| 2| 2| 39.07| 60.93| 2471
0| 2| 66| 38.91| 61.09| 2471
0| 3| 3| 38.70| 61.30| 2465
0| 3| 67| 38.71| 61.29| 2465
...
测试四¶
虽然屏蔽了 ACPI cpufreq ，但是没有彻底解决 lscpu 缓慢问题，但是我发现和 ADM Ryzon处理器随机”冻结”问题 相似的情况，也就是系统此时还是激活了 CPU c-state ，因为检查:
cat /sys/module/intel_idle/parameters/max_cstate
显示输出是:
9
也就是说对于启用了 OS Control Mode 的 Power Management Profile ( ACPI cpufreq )，还是会启用处理器最高达到9的深度c-state。
配置内核，关闭 CPU c-state :
processor.max_cstate=1 intel_idle.max_cstate=0
重启服务器后再次验证， 执行 lscpu 已经不再出现长时间卡顿现象
总结¶
线上早期部署的国产化海光服务器没有配置任何有关电源管理的内核参数，所以当时BIOS即使配置了 ACPI cpufreq 中提到的
OS Control Mode的 Power Management Profile 也没有影响后期上线的服务器启用了 CPU c-state 内核配置，但是国产化海光服务器的硬件BIOS上完全关闭了电源管理功能，所以也没有任何影响(压根底层BIOS就没有激活电源管理，上层OS启用 CPU c-state 内核配置是无效的)
但是，如果将后期服务器的内核参数移植到前期部署的国产化海光服务器，就误打误撞触发了BUG:
自动加载了 ACPI cpufreq 内核模块会硬件限制海光处理器的主频范围，max主频强制为 2.0G Hz(低于最高的2.4G Hz)
即使屏蔽了 ACPI cpufreq 内核模块，也存在因为 ADM Ryzon处理器随机”冻结”问题 缺陷，必须将 CPU c-state 彻底关闭(配置
intel_idle.max_cstate=0)，强制处理器 full run
总之，线上环境是非常容易体现 复杂系统是如何失败的 ，需要:
降低复杂化
透明
标准化