· cloud

cgroup引起的应用延迟

背景

用户发现线上某容器请求 hbase 延迟较大,其他容器无类似现象,发现问题容器宿主机系统 cpu 占用较大(30%左右,正常在 5%以下)。通过 top 查看 lxcfs 占用 cpu 较多(200%以上)。

探究

查看宿主机(内核 4.9.2)top,显示每个 cpu 使用信息。查看最高的 cpu 占用是lxcfs造成的。

strace查看 lxcfs 调用

#查看调用情况,read占用99%
$ strace -p 18521 -c
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 99.82   78.360112       39797      1969           read
  0.11    0.088295         122       722           munmap
  0.01    0.011649         416        28           wait4
  0.01    0.010611          14       736           open
  0.01    0.005685          75        76        18 futex
  0.01    0.005288           7       792           close
  0.01    0.005115          14       366           writev
  0.01    0.004750           7       722           mmap
  0.00    0.003552           5       722           fstat
  0.00    0.002989         107        28           epoll_wait
  0.00    0.002102          17       126           stat
  0.00    0.000202          14        14           socketpair
  0.00    0.000157          11        14           write
  0.00    0.000122           4        28           epoll_create
  0.00    0.000111           8        14           recvmsg
  0.00    0.000104           4        28           epoll_ctl
  0.00    0.000091           3        28           clone
  0.00    0.000071           5        14           setsockopt
  0.00    0.000059           4        14           setns
  0.00    0.000012           1        14           recvfrom
  0.00    0.000011           1        14           sendmsg
  0.00    0.000003           0        14           set_robust_list
  0.00    0.000000           0        14           getpid
------ ----------- ----------- --------- --------- ----------------

# 查看详细情况,大量读取cgroup下memory的调用
$ strace -p 18521 -f -T -tt -o lx.log

cat lx.log
79153 14:20:31.122630 open("/run/lxcfs/controllers/memory//kubepods/burstable/pod7077217d-de6f-11e9-9352-246e96d53468/bcac6516ca5b2a60880fcbc752bf6878ddc77905db71269d852d17f5dc90b148/memory.memsw.limit_in_bytes", O_RDONLY) = 5 <0.000017>

经发现某个 pod 调用的次数明显高于其他 pod,排查到其容器内每隔 2s 执行ps -auf,会调用/proc/pid/stat 其中就有 memory 相关的。

开开心心联系业务将其驱逐,宿主机没有明显变化,再次查看top

top - 13:43:56 up 120 days, 19:21,  1 user,  load average: 6.59, 3.26, 2.34
Tasks: 630 total,   1 running, 629 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0.8 us,  7.1 sy,  0.0 ni, 92.1 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem : 13170992+total, 93100928 free,  7571536 used, 31037456 buff/cache
KiB Swap:        0 total,        0 free,        0 used. 11042460+avail Mem

   PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 20686 root      20   0  141152  49032  17960 S  51.3  0.0   5890:25 cadvisor
115798 root      20   0       0      0      0 D  19.5  0.0   0:09.62 kworker/14:0
 95501 root      20   0       0      0      0 D  17.2  0.0   0:10.11 kworker/0:1
 38620 root      20   0       0      0      0 D  13.9  0.0   0:07.92 kworker/2:1
111178 root      20   0       0      0      0 D  13.9  0.0   0:10.67 kworker/6:0
 58741 root      20   0       0      0      0 D  12.3  0.0   0:10.50 kworker/15:1
104600 root      20   0       0      0      0 D  12.3  0.0   0:05.55 kworker/8:2
 15166 root      20   0       0      0      0 D  10.9  0.0   0:04.44 kworker/16:1
 89483 root      20   0       0      0      0 D  10.9  0.0   0:04.73 kworker/11:0
 30487 root      20   0 3905496 152268  36216 S   9.3  0.1   3060:33 dockerd
 41220 work      20   0  687540 300368  16012 S   4.0  0.2 235:53.07 lottery-service
125923 root      20   0 4892136 181572  58924 S   3.6  0.1  21469:57 kubelet
 ...

发现 cadvisor 占用较高的 cpu,联系以前遇到的问题,cadvisor 也是采集 memory 时变慢,测试居然需要 2 秒多!

$ time cat /sys/fs/cgroup/memory/memory.stat
cache 25691987968
rss 3426922496
rss_huge 2759852032
...

real	0m2.485s
user	0m0.000s
sys	0m2.484s

主要原因是产生了某些僵尸 cgroup(比如反复启动,进程不存在了,但 cgroup 还没来得及回收,cgroup 会反复计算这些 cgroup 的内存会占用),导致 cpu 使用增加相关 issue 以及thread

解决

根本原因还需要进一步分析,临时解决办法,通过手动释放内存

echo 2 > /proc/sys/vm/drop_caches

如果没效果可尝试

echo 3 > /proc/sys/vm/drop_caches

释放后,果然系统 cpu 逐渐恢复正常了,从 falcon 查看 cpu 确实下降了 lxcf-cpu

跟进

经排查,我们使用的内核较旧为(4.9.2);僵尸 cgroup 过多, 导致遍历 cgroup 读取 per_cpu 变量时可能引起锁的争用。

僵尸 cgroup:没有进程运行,并已经被删除的 cgroup,但是所占用的内存并没有被完全回收(inode,dentry 等缓存资源),在读取 memory.stat 仍会计算这部分 cgroup 的缓存空间。

目前该问题在新版的内核(如 5.4)中得到修复,新内核引用新的数据结构解决该问题:每次分配内存时,会即时更新 cgroup 的内存使用情况存储到专用的统计变量,因此读取某个 cgroup 的 mem stat 不会涉及到 per_cpu 变量,可以立即返回。