腾讯游戏开发工程师:Linux 机器 CPU 毛刺问题排查( 二 )

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

  • 如果 CPU 高的情况发生概率很低 , 人为观察比较耗时
  • 不能明确的知道 , 具体在哪个文件的哪个函数
使用gcore最初统计的时候 , 发现 CPU 高的情况会出现 1 秒多的时间 , 如果发现 CPU 高负载时 , 直接调用gcore {pid}的命令 , 可以保留堆栈信息 , 明确具体高负载的位置 。
将使用 gcore 的指令 , 添加到统计工具中取 , 设置 CPU 上门先触发 。
通过gdb看了几个 coredump 文件 , 发现堆栈和函数调用基本一致 。 可以明确的看到 , 大量的耗时发生在了AddActInfoV3这一函数中:
腾讯游戏开发工程师:Linux 机器 CPU 毛刺问题排查文章插图
到此位置 , 我们明确了高计算量发生的具体位置 。
风险点CPU 突然飙升是否存在风险呢?是不是计算资源充足的时候 , 就不会有问题呢?
这个例子中 , 使用的是 SPP 微线程功能 , 每个 Worker 进程只启用一个线程 。
腾讯游戏开发工程师:Linux 机器 CPU 毛刺问题排查文章插图
如果仅仅是因为高计算量卡住 CPU , 正常处理请求的逻辑将很难被调度到 。 这样势必会造成处理请求的延迟增大 , 甚至有超时返回的风险 。
使用 spp 的cost_stat_tool工具利用 spp 自带的统计工具印证这一风险点 , 查看 worker 处理前端请求时延统计信息 , 执行命令./cost_stat_tool -r 1:
腾讯游戏开发工程师:Linux 机器 CPU 毛刺问题排查文章插图
上边的例子中 , 统计发生配置更新前后的 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--tt-darkmode-color: #8F9BAB;">过滤出一条符合条件的请求:
腾讯游戏开发工程师:Linux 机器 CPU 毛刺问题排查文章插图
在该条记录上右键 -> Follow -> TCP Stream , 可以查看该请求前后的 IP 包:
腾讯游戏开发工程师:Linux 机器 CPU 毛刺问题排查文章插图
上边 4 个包分别是:
  1. +0ms 客户端发送请求至服务端
  2. +38ms 服务端回复 ACK , 无数据
  3. +661ms 服务端发送返回至客户端
  4. +662ms 客户端回复 ACK
详细看了包中的内容为一条普通请求 , 逻辑简单 , 应该在 20ms 内返回 。 而此时的该进程使用 CPU 也确实为高负载的情况:
腾讯游戏开发工程师:Linux 机器 CPU 毛刺问题排查文章插图
上述统计相互印证:
  • CPU 高时 , 正常的网络请求也会被阻塞住(回复 ACK 需要 38ms , 低于 40ms , 与TCP 延迟确认无关)
  • 平时只需要 20ms 能返回的请求 , 耗时了 660ms
CPU 突然飚高有风险 , 需要认真对待 。