CPU load高但CPU usage低问题排查

讲故事最近服务总是出现 cpu load高的告警，且告警经常还出现在低峰期的凌晨，所以很明显不是用户流量导致的负载高，但是 cpu buzy却很低。查看内存使用情况：mem.memused 接近100%，查看磁盘情况：swap.used周期性(30分钟左右)的较高， disk.io.util 低，但是 disk.io.avgqu-sz（平均请求队列的长度）周期性（30分钟左右）的较高，且和 cpu

研发之道

7141人浏览 · 2020-10-19 18:44:13

研发之道 · 2020-10-19 18:44:13 发布

讲故事

最近服务总是出现 cpu load高的告警，且告警经常还出现在低峰期的凌晨，所以很明显不是用户流量导致的负载高，但是 cpu buzy却很低。查看内存使用情况：mem.memused 接近100%，查看磁盘情况：swap.used周期性(30分钟左右)的较高， disk.io.util 低，但是 disk.io.avgqu-sz（平均请求队列的长度）周期性（30分钟左右）的较高，且和 cpu load高同频。后续经排查机器上上 crontab -l，查看周期为30分钟的定时任务，发现定时任务为 puppet，并查看该定时任务的日志里的执行时间和 cpu load高也对得上。因此以上很多现象同频共振，我们只能说明这些现象具有强相关性，就像“啤酒和尿布的故事“，但是具体的逻辑归因链是怎样的？链上的每一个环节都需要证据支撑。

结论

`mem.memused` 高(OS内存不足)
			-> `swap.used`高 -> `disk.io.avgqu-sz`磁盘操作排队 -> "cpu load"高 -> 触发告警
`puppet`周期任务大量磁盘读

分析问题

我们的机器内存8G。JVM 参数：

-Xmx6g -Xms6g -Xmn3g

问题一：为什么 mem.memused 一直平稳接近8G？而jvm 定义6G才使用一半，不可能打满8G？memused = MemTotal - MemFree - Buffers/Cached。看统计方式的公式可知，只要jvm不向操作系统释放内存，Buffers/Cached 和MemFree的大小就不会变化。jvm的GC只是逻辑释放内存，但依然被jvm所管理，并不是物理释放（所以top查看该Java进程RES列使用内存6G左右）。所以像jvm.memory.used指标才会敏感的跟踪GC带来的jvm内存变化。从操作系统的层面来说是已经接近使用6G了。
问题二：为什么内存使用如此高导致使用了swap分区？

申请机器时预选中安装了tomcat（事实上不需要），导致服务部署后，机器上起了两个Java进程，其中一个是tomcat启动的，通过下面命令观察到其内存使用量1.5G左右。

[sankuai@set-gh-klsearch-srsbiz01 ~]$ ps -p 3408 -o rss,vsz
  RSS    VSZ
1554172 8672328

随着业务服务JVM内存向操作系统申请的内存越来越多，可以通过top命令看到RES列逐渐变大至接近6G。总体内存占用 = JVM1（6G） + JVM2（tomcat 1.5G）+ 非JVM内存。导致OS最终可用内存不足，进而使用到swap分区

问题三：为什么 cpu load 高而 cpu usage低？
等待磁盘I/O完成的进程过多，导致进程队列长度过大，但是cpu运行的进程却很少，这样就体现到负载过大了，cpu使用率低。
问题四：为什么磁盘请求队列排队较多会导致 cpu load高？

uptime和top等命令都可以看到load average指标，从左至右三个数字分别表示1分钟、5分钟、15分钟的load average：

$ uptime
11:44:47  up 46 days 14:54,  2 users,  load average: 2.98, 3.08, 3.02

如果平均值为 0.0，意味着系统处于空闲状态
如果 1min 平均值高于 5min 或 15min 平均值，则负载正在增加
如果 1min 平均值低于 5min 或 15min 平均值，则负载正在减少
如果它们高于系统 CPU 的数量，那么系统很可能会遇到性能问题（视情况而定）

在 Linux 中，对于整个系统而言，load averages 是 “system load averages”，测量正在运行和等待运行的线程数（CPU，磁盘，不间断锁），包括uninterruptible sleep的进程数量。不像其他操作系统的 cpu load的定义，Linux里衡量的不仅仅是CPU资源的负载了。优点：包含了对不同资源的需求。

当看到load average很高的时候，你不知道是runnable进程太多还是uninterruptible sleep进程太多，也就无法判断是CPU不够用还是IO设备有瓶颈。

进程在cpu上面运行需要访问磁盘文件，这个时候cpu会向内核发起调用文件的请求，让内核通过DMA方式去磁盘取文件，这个时候会切换到其他进程或者空闲，这个任务就会转换为uninterruptible sleep状态。当这种读写请求过多就会导致uninterruptible sleep状态的进程过多，从而导致负载高，cpu低的情况。

sched/loadavg.h:

#define LOAD_FREQ   (5*HZ+1) /* 5 sec intervals */

sched/loadavg.c

* The global load average is an exponentially decaying average of nr_running +
 * nr_uninterruptible.
 *
 * Once every LOAD_FREQ:
 *
 *   nr_active = 0;
 *   for_each_possible_cpu(cpu)
 *  nr_active += cpu_of(cpu)->nr_running + cpu_of(cpu)->nr_uninterruptible;
 *
 *   avenrun[n] = avenrun[0] * exp_n + nr_active * (1 - exp_n)

HZ is the kernel timer frequency, which is defined when compiling the kernel. On my system, it’s 250:

% grep "CONFIG_HZ=" /boot/config-$(uname -r)
CONFIG_HZ=250

解决问题

去掉预安装的tomcat软件
减少JVM配置的最大堆使用

问题得以解决。😄 🎉️ ！

参考资料：

附录：

top命令：

[root@localhost ~]# top
top - 12:13:22 up 167 days, 20:47,  2 users,  load average: 0.00, 0.01, 0.05
Tasks: 272 total,   1 running, 271 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0.0 us,  0.1 sy,  0.0 ni, 99.9 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem : 65759080 total, 58842616 free,   547908 used,  6368556 buff/cache
KiB Swap:  2097148 total,  2097148 free,        0 used. 64264884 avail Mem
................
  
对上面第三行的解释：
us（user cpu time）：用户态使用的cpu时间比。该值较高时，说明用户进程消耗的 CPU 时间比较多，比如，如果该值长期超过 50%，则需要对程序算法或代码等进行优化。
sy（system cpu time）：系统态使用的cpu时间比。
ni（user nice cpu time）：用做nice加权的进程分配的用户态cpu时间比
id（idle cpu time）：空闲的cpu时间比。如果该值持续为0，同时sy是us的两倍，则通常说明系统则面临着 CPU 资源的短缺。
wa（io wait cpu time）：cpu等待磁盘写入完成时间。该值较高时，说明IO等待比较严重，这可能磁盘大量作随机访问造成的，也可能是磁盘性能出现了瓶颈。
hi（hardware irq）：硬中断消耗时间
si（software irq）：软中断消耗时间
st（steal time）：虚拟机偷取时间