Jason Pan

CPU毛刺问题排查

潘忠显 / 2020-09-28

本文排查一个Linux机器CPU毛刺问题，排查过程中不变更进程状态、也不会影响线上服务，最后还对CPU毛刺带来的风险进行了分析和验证。

本文中提到CPU统计和产生core文件的工具详见 simple-perf-tools 仓库。

问题描述

某服务所在机器统计显示，其CPU使用率在高峰时段出现毛刺。

暂时未收服务调用方的不良反馈。

tnm-cpu-util

初步排查

查看CPU 1分钟平均负载，发现1分钟平均负载有高有低，波动明显。说明机器上有些进程使用CPU波动很大。

tnm-cpu-average-util

登录机器排查进程，使用top指令。因为CPU会明显上升，重点怀疑使用CPU总时间高的进程，在打开top后，使用shift +t可以按照CPU TIME进行排序。

simple-top-cmd

直观的看，有几个spp_worker相关的进程使用CPU TIME相对较高。

第一个进程因为启动的时间比较长，所以CPU TIME也比较大。可以使用下面的脚本，计算各个进程从各自拉起后CPU使用率：

uptime=`awk '{print $1}' /proc/uptime` # why is it too slow indocker?
hertz=`zcat /proc/config.gz | grep CONFIG_HZ= |awk -F"=" '{print $2}'`
awk -v uptime=$uptime -v hertz=$hertz -- '{printf("%d\t%s\t%11.3f\n", $1, $2, (100 *($14 + $15) / (hertz * uptime - $22)));}' /proc/*/stat 2> /dev/null | sort  -gr -k +3 | head -n 20

看到的也是这些spp_worker使用CPU相对要高一些：

cpu-average-utilization

选其中的一个PID为45558的Worker进程监控器CPU使用率：

total-and-sys-cpu-of-process

可以发现其CPU大部分情况很低，但是在某一个时间点会升高，持续1秒左右。而且大部分时间是耗费在用户态，而非系统调用。

而《Linux Agent采集项说明 - CPU使用率》中描述的CPU使用率的采样策略为：

Linux Agent每分钟会采集4次15秒内的CPU平均使用率。为了避免漏采集CPU峰值，网管Agent取这一分钟内四次采集的最大值上报。

因为采样可能采到高点或者低点，当1分钟内出现CPU飙升，则会表现为尖峰；如果四次都没有出现飙升，则表现为低谷。

至此，已经能确认是这批Worker进程引起了这种毛刺，但具体是哪部分代码有问题还需要进一步排查。

进一步排查

前边确认了没有太多的系统调用，所以不必使用strace工具。

使用perf工具

使用perf工具进行查看。具体的命令是perf top -p 45558，在低CPU使用率的时候：

perf-top-common

但是当CPU飚上去的时候，perf采样的位置变成如下这样：

perf-top-high-cpu

看一下红框的位置，可以发现可能是配置更新部分有问题，因为：

通过观察perf结果的方法，虽然能够猜测大计算量的位置，但是有两个不便之处：

使用gcore

最初统计的时候，发现CPU高的情况会出现1秒多的时间，如果发现CPU高负载时，直接调用gcore {pid}的命令，可以保留堆栈信息，明确具体高负载的位置。

将使用gcore的指令，添加到统计工具中取，设置CPU上门限触发。

通过gdb看了几个coredump文件，发现堆栈和函数调用基本一致。可以明确的看到，大量的耗时发生在了AddActInfoV3这一函数中：

gdb-gcore

到此，我们明确了高计算量发生的具体位置。

风险点

CPU突然飙升是否存在风险呢？是不是计算资源充足的时候，就不会有问题呢？

这个例子中，使用的是SPP微线程功能，每个Worker进程只启用一个线程。

gdb-thread

如果仅仅是因为高计算量卡住CPU，正常处理请求的逻辑将很难被调度到。这样势必会造成处理请求的延迟增大，甚至有超时返回的风险。

使用spp的cost_stat_tool工具

利用spp自带的统计工具印证这一风险点，查看worker处理前端请求时延统计信息，执行命令./cost_stat_tool -r 1：

cost-statistics

上边的例子中，统计发生配置更新前后的5秒钟内，worker处理的231个请求中，有3个请求的处理时间超过500ms，远高于普通请求。

使用tcpdump抓包确认

因该服务没有打开详细的日志，想要进一步验证超过500ms的这些请求也是正常处理的请求，而非异常请求，可以通过抓包来分析。

tcpdump -i any tcp port 20391 -Xs0 -c 5000 -w service_spp.pcap

通过wireshark打开，需要过滤出返回时间 - 请求时间 > 500ms的相关请求。翻译成wireshark过滤器的表达式则是：

tcp.time_delta > 0.5 && tcp.dstport != 20391

过滤出一条符合条件的请求：

wireshark-filter

在该条记录上右键 -> Follow -> TCP Stream，可以查看该请求前后的IP包：

tcpdump-one-connection

上边4个包分别是：

  1. +0ms 客户端发送请求至服务端
  2. +38ms 服务端回复ACK，无数据
  3. +661ms 服务端发送返回至客户端
  4. +662ms 客户端回复ACK

详细看了包中的内容为一条普通请求，逻辑简单，应该在20ms内返回。而此时的该进程使用CPU也确实为高负载的情况：

cpu-coresponding-to-tcpdump

上述统计相互印证：

CPU突然飚高有风险，需要认真对待。

附：Docker子机中遇到的几个问题

  1. docker中使用getconf时要注意，可能不对。(可能取到的是母机的参数?)
hertz=`getconf CLK_TCK` # doesn't work in a doker!!!

比如这里获取Hertz的，直接使用getconf CLK_TCK得到的是100， 但是根据uptime可以判断出实际是250

  1. 直接cat /proc/uptime特别慢，（为什么?）
$ time cat /proc/uptime 
25473271 0

real        0m0.464s