Kubelet 组件占用 CPU 过高的解决思路

2020-11-27 本文已影响0人陈光辉_akr8s

问题发现

最近通过监控发现，我们容器云平台其中一个 kubernetes 集群的所有 worker 节点的 kubelet 进程均长时间占用 CPU 过高，奇怪的是 master 节点跟 monitor 节点都没有这个问题。
- 我们的第一反应是跟负载有关系，这些 worker 节点都运行了很多我们的业务 Pod
- 幸运的是，这个集群是我们的开发集群，并且这些 worker 节点都是物理机，资源是充足的，还没影响到业务，所以我们有充足的排查处理时间

环境信息

Kubernetes: v1.18.8
操作系统：CentOS Linux release 7.6.1810 (Core) 
kernel：4.4.227-1.el7.elrepo.x86_64

排查过程

使用工具
- sysstat version 11.5.5
- perf
- go tool
- FlameGraph
- htop
分析过程

首先我们到 worker 节点使用 htop 查看 cpu 使用情况，很容易就发现了 kubelet 的 cpu 使用情况是异常的。

kubelet_cpu.png
使用 pidstat 同样可以明显发现 kubelet 占用 cpu 的时间都是耗在了内核态

# pidof kubelet
391280
# pidstat -p 391280 1 5
Linux 4.4.227-1.el7.elrepo.x86_64 (rancher-dg-tn9)      11/20/2020      _x86_64_        (72 CPU)

07:54:45 PM   UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
07:54:46 PM     0    391280    4.95  100.00    0.00    0.00  100.00    34  kubelet
07:54:47 PM     0    391280    0.00  100.00    0.00    0.00  100.00    34  kubelet
07:54:48 PM     0    391280    0.00  100.00    0.00    0.00  100.00    34  kubelet
07:54:49 PM     0    391280    3.00  100.00    0.00    0.00  100.00    34  kubelet
07:54:50 PM     0    391280    3.00  100.00    0.00    0.00  100.00    34  kubelet
Average:        0    391280    4.30  100.00    0.00    0.00  100.00     -  kubelet

因为所有的 worker 节点都是这个情况，所以我们想着先在一个节点重启 kubelet 试试，结果重启完 kubelet 之后问题依然还在。到这里就想着事情可能没这么简单了，需要进一步深入分析 Linux 的性能问题。
所以我们 strace 了 kubelet 的进程，发现 syscall 有大量的 futex error，cpu 时间都耗在这里，说明了它可能在等待资源，而资源还没准备好。

# pidof kubelet
391280
# strace -cp 391280
strace: Process 391280 attached
strace: Process 391280 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 99.80 2623.789827       41644     63005     11889 futex
  0.10    2.721893      544378         5           epoll_wait
  0.08    1.989361        1572      1265           epoll_pwait
  0.01    0.156758          19      8173         2 newfstatat
  0.00    0.109730          32      3354       339 read
  0.00    0.101180          21      4602         1 readlinkat
  0.00    0.059750          20      2972       526 epoll_ctl
  0.00    0.039303          16      2422           fcntl
  0.00    0.036715          24      1477           openat
  0.00    0.030070          44       674           write
  0.00    0.027179         204       133           nanosleep
  0.00    0.025634          17      1484           close
  0.00    0.016708          36       457           getdents64
  0.00    0.015895          13      1169           fstat
  0.00    0.015259         206        74           sched_yield
  0.00    0.002846         218        13         7 connect
  0.00    0.001864          38        49           setsockopt
  0.00    0.000938          72        13           socket
  0.00    0.000820          48        17           madvise
  0.00    0.000518          34        15           getpeername
  0.00    0.000470          52         9           getsockopt
  0.00    0.000450          30        15           getsockname
  0.00    0.000427          35        12           rt_sigreturn
  0.00    0.000319          22        14           lseek
  0.00    0.000049          24         2         2 unlinkat
  0.00    0.000007           7         1           getrandom
------ ----------- ----------- --------- --------- ----------------
100.00 2629.143970                 91426     12766 total

strace -tt -p Pid 也只是发现了一些 FUTEX_WAIT_PRIVATE 的 Connection timed out，还是没能太好的说明问题。

# strace -p 391280 -T -v -e trace=all -ff 2>&1 | egrep '<[1-9]\.[1-9]'

10:39:35.050828 futex(0x7027320, FUTEX_WAIT_PRIVATE, 0, {tv_sec=3, tv_nsec=984755078}) = -1 ETIMEDOUT (Connection timed out) <3.984847>
10:39:39.035764 futex(0xc0021d4148, FUTEX_WAKE_PRIVATE, 1) = 1 <0.000012>
10:39:39.035822 futex(0xc002ab12c8, FUTEX_WAKE_PRIVATE, 1) = 1 <0.000011>
10:39:39.035861 futex(0x7027320, FUTEX_WAIT_PRIVATE, 0, {tv_sec=8, tv_nsec=935276896}) = -1 ETIMEDOUT (Connection timed out) <8.935371>
10:39:47.971297 futex(0x7022130, FUTEX_WAKE_PRIVATE, 1) = 1 <0.000009>
10:39:47.971337 futex(0x7022030, FUTEX_WAKE_PRIVATE, 1) = 1 <0.000008>
10:39:47.971364 futex(0xc00084c148, FUTEX_WAKE_PRIVATE, 1) = 1 <0.000008>
10:39:47.971388 futex(0xc0002024c8, FUTEX_WAKE_PRIVATE, 1) = 1 <0.000008>
10:39:47.971411 futex(0x7027320, FUTEX_WAIT_PRIVATE, 0, {tv_sec=2, tv_nsec=65115694}) = -1 ETIMEDOUT (Connection timed out) <2.065206>

这个时候我们想到了 perf，很多同学应该都很了解，perf 是非常好用的 Linux 性能分析工具，所以我们想着用 perf 来收集一些数据，再把它生成火焰图来分析。
- perf 的用法跟参数可以使用 perf --help 查看帮助文档，还是比较简单的
- 先收集数据 perf.data
- 然后使用 perf script 对 perf.data 进行解析
- 最后用 FlameGraph 工具生成火焰图

# perf record -F 99 -p 391280 -g -- sleep 30
# perf script -i perf.data &> perf.unfold
# git clone https://github.com/brendangregg/FlameGraph.git
# cp perf.unfold FlameGraph/
# cd FlameGraph/
# ./stackcollapse-perf.pl perf.unfold &> perf.folded
# ./flamegraph.pl perf.folded > perf_kubelet.svg

perf_kubelet.png

到这里我们稍微有点眉目了，sys_read 函数执行的时间非常长，再看到顶层的两个函数 mem_cgroup_read_events/mem_cgroup_read_stat，占据的宽度最大，说明了这两个函数可能存在性能问题。而这两个函数就是 cgroup 相关的，所以很自然我们就会想到可能是内核的 cgroup 有问题了。
再来看看使用 go pprof 工具通过 APiserver 得到的节点的 kubelet 火焰图
- 需要在节点安装 golang 环境，这里我们使用 golang 容器
- 在 master 节点启动 kubectl proxy 代理 APIserver
- 使用 FlameGraph 工具生成火焰图

# kubectl proxy --address='0.0.0.0'  --accept-hosts='^*$'
# docker run -d --name golang-env --net host golang:latest sleep 3600
# go tool pprof -seconds=60 -raw -output=kubelet.pprof http://APIserver:8001/api/v1/nodes/node_name/proxy/debug/pprof/profile
# ./stackcollapse-go.pl go_kubelet.pprof > go_kubelet.out
# ./flamegraph.pl go_kubelet.out > go_kubelet.svg

go_kubelet.png

看到 go pprof 工具收集的数据生成的火焰图之后，再结合前面的分析，我们基本可以串起来了
- kubelet 内置的 cAdvisor 在调用 read() 函数非常慢，从 read 读取的内容和前面两个 mem_cgroup 函数来看，那些 read() 调用是在读取 cgroup 的 memory.stat 文件
- 这个文件用于描述系统的内存使用以及 cgroup 的限制。cAdvisor 通过轮询这个文件来获取容器所使用的资源情况
- 我们尝试手工读取一下这个文件
  - 好家伙，用时 9s 多

# time cat /sys/fs/cgroup/memory/memory.stat > /dev/null
real    0m9.115s
user    0m0.000s
sys     0m9.112s

这个时候，我们也搜索到了一个 issue，参考 issue 我们也更深入了解了一下 cgroup
关于内存的 cgroup，它负责管理与统计命名空间（容器）内的内存使用情况。当该 cgroup 中的所有进程退出时，内存 cgroup 会被 Docker 释放。但是，“内存”不仅是进程的内存，而且虽然进程内存的使用量已经消失，但事实证明，内核还为缓存空间分配了内存，例如 dentries 和 inode（目录和文件元数据），这些内容被缓存到内存 cgroup 中。从这个问题可以看出：
- 僵尸 cgroup：那些没有进程运行并被删除的 cgroup 仍然持有一定得内存空间
- 与其在 cgroup 释放的时候遍历所有的缓存页（这也可能很慢），内核会惰性地等待这些内存需要用到的时候再去回收它们，当所有的内存页被清理以后，相应的 cgroup 才会最后被回收。在被回收之前，这些 cgroup 仍然会被计入统计信息中。
- 从性能的角度来看，它们通过分期回收每个页面来摊销直接整体回收的巨大耗时，选择快速地进行初始的清理，但这种方式会保留一些缓存在内存中。但这也没什么问题，当内核回收缓存中的最后一页内存时，cgroup 最终会被清理，因此这并不是一个“泄漏”。
- 不幸的是，我们遇到的这个问题在于 memory.stat 执行搜索的方式，比如在我们的服务器内核时 4.4，这个版本的实现是递归的算法进行查询，再加上我们服务器一般都有大量的内存空间，这意味着最后一次内存缓存回收并清理僵尸 cgroup 可能要花很长时间。

处理方法

了解到这里，我们遇到的这个问题的临时解决方法是：
- 释放节点系统范围内的 dentries 和 inode 缓存；这并不是最终的解决方案，但可以验证问题的原因。
- 最终的解决方案，还是要升级内核，在社区 kernel 5.2+ 的版本有个 commit 优化了 cgroup stats 查询性能

# 目前处理
echo 2 > /proc/sys/vm/drop_caches

# 后续继续观察是否需要升级 kernel

安信证券容器云团队

Kubelet 组件占用 CPU 过高的解决思路

问题发现

环境信息

排查过程

处理方法

猜你喜欢

热点阅读