问题发现
- 最近通过监控发现，我们容器云平台其中一个 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
安信证券容器云团队
有疑问加站长微信联系（非本文作者）
