排查集群的一些问题

返回到博客

排查集群的一些问题

Zoe

2020-12-12

1 MINS

虽然是开发工作，在保障稳定性中，有时候会有很多重要单不是特别紧急的问题。我一般都是集中一起安排时间排查，这里做一些记录和汇总，不具备任何系统性的知识内容。

每段都是独立补充，所以时间表述上可能与文章不一致。

容器关闭失败#

自从隔壁组的服务治理上线以来，一直就收到集群内容器关闭失败的报警。不过一直也没人关注，不实际影响业务。但是影响宿机器的资源使用。同时这么多的报警也影响运维的响应效率。

下午正好有空就抽空进行了一次问题排查。

情况1

登录上机器，找到找到envoy sidecar的进程。先看下调用栈，

1[root@wc-testk8s-0-103 cgroup]# cat /proc/291967/stack
2[<ffffffffa0072807>] do_wait+0x1d7/0x250
3[<ffffffffa0073c49>] kernel_wait4+0x89/0x140
4[<ffffffffa0073d86>] SYSC_wait4+0x86/0x90
5[<ffffffffa0073e2e>] SyS_wait4+0xe/0x10
6[<ffffffffa0124183>] zap_pid_ns_processes+0x103/0x1a0
7[<ffffffffa00739b9>] do_exit+0xb29/0xbe0
8[<ffffffffa0073aef>] do_group_exit+0x3f/0xb0
9[<ffffffffa007fed6>] get_signal+0x166/0x780
10[<ffffffffa001a2c7>] do_signal+0x37/0x6a0
11[<ffffffffa0002032>] exit_to_usermode_loop+0x5b/0xc5
12[<ffffffffa0001cc7>] do_syscall_64+0xe7/0x120
13[<ffffffffa0c00081>] entry_SYSCALL_64_after_hwframe+0x3d/0xa2
14[<ffffffffffffffff>] 0xffffffffffffffff

zap_pid_ns_processes应该是等待 pid namespace 下其他进程的退出。我找到另一个（子）进程362091，同样地看看stack,

1[root@wc-testk8s-0-103 cgroup]# cat /proc/362091/stack
2[<ffffffffa0ae9918>] call_rwsem_down_read_failed+0x18/0x30
3[<ffffffffa0235da2>] iterate_supers+0xa2/0x110
4[<ffffffffa0269ba4>] sys_sync+0x44/0xb0
5[<ffffffffa0001c46>] do_syscall_64+0x66/0x120
6[<ffffffffa0c00081>] entry_SYSCALL_64_after_

在调用sync，hang在call_rwsem_down_read_failed。这是进程名是s6-sync。

看来是容器里使用s6相关的东西。找到相关的项目地址 https://github.com/just-containers/s6-overlay 发现在 CHANGELOG 中有如下说明：

Version 1.21.8.0 Up to and including version 1.21.8.0, the init system would call s6-sync to sync disks when the container exited. This actually syncs all block devices on the hosts, which is likely not what you want to do. As of version 1.22.0.0, this is disabled by default, see the README on how to re-enable it.

一直到1.21.8的版本在容器退出时，都会去调用s6-sync。 1.22默认是关闭的。先让业务方升级这个版本把。

那么为什么会卡在sync上呢？有空再研究一下。

情况2

首先先找到容器ID，并查看 dockerd 的日志 journalctl -u docker 。发现下面日志，

16 10 16:09:15k8s-0-176 dockerd[1751]: time="2021-06-10T16:09:15.458629778+08:00" level=info msg="
2Container 10f0451e1345 failed to exit within 10 seconds of kill - trying direct SIGKILL"
36 10 16:11:06k8s-0-176 dockerd[1751]: time="2021-06-10T16:11:06.286046073+08:00" level=info msg="
4Container 10f0451e1345f5028f636e2b09c9f8204e55a01f5f09f2e57de3c17d3f93f492 failed to exit within 30
5seconds of signal 15 - using the force"
66 10 16:11:16k8s-0-176 dockerd[1751]: time="2021-06-10T16:11:16.301226981+08:00" level=info msg="
7Container 10f0451e1345 failed to exit within 10 seconds of kill - trying direct SIGKILL"

说明容器确实无法被dockerd关闭。手动找到进程号 docker inspect，kill -9 也无发杀掉进程。ps 发现进程 CMD 有 [] 说明是在内核态，而且是 sleep 状态，说明大概率是卡在了系统调用上，我们查看进程的CPU~为0。strace -p PID 发现也无法执行，会卡住。

查看 wchan 为 do_wait 查看 stack，

1[<ffffffffa9072807>] do_wait+0x1d7/0x250
2[<ffffffffa9073c49>] kernel_wait4+0x89/0x140
3[<ffffffffa9073d86>] SYSC_wait4+0x86/0x90
4[<ffffffffa9073e2e>] SyS_wait4+0xe/0x10
5[<ffffffffa9124183>] zap_pid_ns_processes+0x103/0x1a0
6[<ffffffffa90739b9>] do_exit+0xb29/0xbe0
7[<ffffffffa9073aef>] do_group_exit+0x3f/0xb0
8[<ffffffffa907fed6>] get_signal+0x166/0x780
9[<ffffffffa901a2c7>] do_signal+0x37/0x6a0
10[<ffffffffa9002032>] exit_to_usermode_loop+0x5b/0xc5
11[<ffffffffa9001cc7>] do_syscall_64+0xe7/0x120
12[<ffffffffa9c00081>] entry_SYSCALL_64_after_hwframe+0x3d/0xa2
13[<ffffffffffffffff>] 0xffffffffffffffff

又是等待命名空间下的进程退出。继续找到相关的进程查看stack，

1[<ffffffffc08766ce>] __ceph_do_pending_vmtruncate+0x4e/0x260 [ceph]
2[<ffffffffc0876f95>] __ceph_setattr+0x665/0x9b0 [ceph]
3[<ffffffffc087732c>] ceph_setattr+0x4c/0x80 [ceph]
4[<ffffffffa9253124>] notify_change+0x2f4/0x440
5[<ffffffffa922e995>] do_truncate+0x75/0xc0
6[<ffffffffa92418c3>] path_openat+0xb33/0x1480
7[<ffffffffa9243c61>] do_filp_open+0x91/0x100
8[<ffffffffa922ff14>] do_sys_open+0x124/0x210
9[<ffffffffa923001e>] SyS_open+0x1e/0x20
10[<ffffffffa9001c46>] do_syscall_64+0x66/0x120
11[<ffffffffa9c00081>] entry_SYSCALL_64_after_hwframe+0x3d/0xa2
12[<ffffffffffffffff>] 0xffffffffffffffff

看上去和ceph相关，查看 ceph的代码，这个函数应该是需要链接网络的，所以一直卡在这里。我们查看进程的命名空间，

1dr-x--x--x 2 root root 0 6 11 10:08 .
2dr-xr-xr-x 9 root root 0 6 9 17:21 ..
3lrwxrwxrwx 1 root root 0 6 11 10:08 cgroup
4lrwxrwxrwx 1 root root 0 6 11 10:08 ipc
5lrwxrwxrwx 1 root root 0 6 11 10:08 mnt
6lrwxrwxrwx 1 root root 0 6 11 10:08 net
7lrwxrwxrwx 1 root root 0 6 11 10:08 pid -> pid:[4026536204]
8lrwxrwxrwx 1 root root 0 6 11 10:08 pid_for_children
9lrwxrwxrwx 1 root root 0 6 11 10:08 user -> user:[4026531837]
10lrwxrwxrwx 1 root root 0 6 11 10:08 uts

发现，网络命名空间已经没有了。那么，问题会不会是出现在这里呢？

apiserver 内存问题#

听运维说这是一个困扰集群A很久的问题。 master节点上内存被apiserver占掉10G+。而且还有其他自研发controller会OOM。

这也没什么好说的，先pprof抓处理看把。默认是打开调试的。

1kubectl proxy
2go tool pprof "https://127.0.0.1:8001/debug/pprof/heap?seconds=120" --mem
3go tool pprof --http :9090 xxx.pb.gz

已经很明显了，大部分都是RS的反序列化操作。这是不应该的，RS又没有其他资源使用频繁。

那么只有一个可能，那就是RS泄漏了。要么是垃圾回收有问题，要么是版本设置错了。

先手动删除一下，

1kubectl get rs -A|awk '{print $1 " " $2 " " $3 $4 $5}'|grep "000$" > rs.list.0
2while read p; do
3ns=`echo $p|awk '{print $1}'`
4name=`echo $p|awk '{print $2}'`
5kubectl delete rs -n $ns $name &
6done < rs.list.0

重启后，apiserver内存由 13G 降低至4G，同时controller也降低到小于1G。

查看deployment资源发现都没有设置revisionHistoryLimit这个字段。

安道理说，没有设置应该是10才对，至少文档上是这么写的。

后面处理是让同事修改部署模块的代码，设置spec.revisionHistoryLimit 的值为10即可。

ipam 进程 hang 问题#

最近在做etcd的去单点，将ipam使用的etcd升级为了3节点，同时也做了https。

内部ipam是比较早的代码，我来之前就有了，是之前的同事写的，一直都没有升级过。

现在同事进行的修改代码，用的是仓库最新的代码（有坑）。但是部署测试环境后发现，会导致pod创建失败，同时伴随着这个进程一直不退出。一般来说这个就是一个命令调用一下会马上退出来的。

用老版本就没有问题，当时一度以为是etcd集群搭建或者https的问题。从集群单节点到http，一步步回退。发现问题还是依旧。

直到我把同事新改代码都回退掉，也就是用仓库里已经存在的代码，编译测试发现也是有问题。那就基本排除了etcd集群或client的关系了。

幸好，运维没有杀掉进程，先看看进程的调用栈，

1[<ffffffff930b743e>] wait_woken+0x6e/0x90
2[<ffffffff934bcdc4>] n_tty_read+0x3e4/0x920
3[<ffffffff934b8072>] tty_read+0x92/0xf0
4[<ffffffff932325e7>] __vfs_read+0x37/0x140
5[<ffffffff9323277c>] vfs_read+0x8c/0x130
6[<ffffffff93232d15>] SyS_read+0x55/0xc0
7[<ffffffff93001c46>] do_syscall_64+0x66/0x120
8[<ffffffff93c00081>] entry_SYSCALL_64_after_hwframe+0x3d/0xa2
9[<ffffffffffffffff>] 0xffffffffffffffff

tty_read，看上去没什么异常，应该是正常的等待标准输入。

本来以为是卡在ADD或者CHECK的COMMAND上的。

最后在开发环境测试发现，其他命令正常，只有VERSION这一个会卡住。

这个命令完全是cni自己实现的，难道是cni库的bug吗？

看下go.mod中cni的版本是0.6.0。直接升级到最新版本0.8.1并重新适配一下，

1skel.PluginMain(cmdAdd, cmdDel, func(*skel.CmdArgs) error { return nil }, version.All, "")

编译后运行，

1(base) thsipam git:(leak) CNI_COMMAND=VERSION ./xxipam
2{"cniVersion":"0.4.0","supportedVersions":["0.1.0","0.2.0","0.3.0","0.3.1","0.4.0"]}

这就正常了。

所以，问题是出在 cni 这个库的STDIN处理上。

我们继续跟一下代码，发现即便是VERSION这个命令，也去读取了 STDIN , ioutil.ReadAll(t.Stdin)。这里自然就会一直堵塞，无法读取到内容。

看下新版本，加了一下判断，

1if cmd == "VERSION" {
2    t.Stdin = bytes.NewReader(nil)
3}

这个修复首次出现在2018年 5月的 v0.7.0-alpha0 版本中。

kube-proxy CPU 使用率高问题#

有几个集群使用的ipvs模式，但是cpu一直占用很高基本在2核及以上，按照道理来说， kube-proxy 这是更新规则，不应该这么高的。集群版本1.14，短时间内升级也不太现实，就先排查解决这个问题。

排查#

在200%左右，出现 strace 无法抓到信息的情况；在100%左右，抓到的系统调用基本符合预期；

环境： docker-0-25

增加pprof进行观察， kube-proxy --profiling

在此之前，通过strace也能观察到syscall6占据大量的CPU

修改升级策略为 OnDelete, 增加命令，重启Pod

注意修改配置文件中的 enableProfiling: true

测试 curl 0:10249/debug/pprof/profile?second=120

抓下数据 go tool pprof "127.0.0.1:10249/debug/pprof/profile?seconds=120"

解压 /root/pprof/pprof.kube-proxy.samples.cpu.003.pb.gz

使用 google/pprof 打开 pprof -http=:9000 pprof.kube-proxy.samples.cpu.003.pb

看上去很明显了：realIpGetter.NodeIPs这个占用太多的时间。

解决方案#

确认NodeIPs函数无需频繁调用后，进行结果的缓存
增加缓存结果，缓存时间为15分钟，对于机器IP变动来说，这足够使用

1// realIPGetter is a real NodeIP handler, it implements IPGetter.
2type realIPGetter struct {
3    // nl is a handle for revoking netlink interface
4    nl NetLinkHandle
5    // TODO: use x.Cache utils
6    _lastResult []net.IP
7    _lastReserr error
8    _lastTimeAt time.Time
9    _cacheTimeout time.Duration
10    _lock sync.Mutex
11}
12
13func (r *realIPGetter) NodeIPs() (ips []net.IP, err error) {
14    r._lock.Lock()
15    defer r._lock.Unlock()
16    // get data from cache first if no error and not expiry
17    t := time.Now()
18    expiryAt := r._lastTimeAt.Add(r._cacheTimeout)
19    if r._lastReserr == nil && t.Before(expiryAt) {
20        klog.V(4).Infof("NodeIPs call result return from cache (expired in %v): %v", t.Sub(expiryAt), r._lastResult)
21        return r._lastResult, nil
22    }
23
24    defer func(){
25        r._lastReserr = err
26        if err == nil {
27            klog.V(4).Infof("NodeIPs call directlly, and cache the result: %v", ips)
28            r._lastResult = ips
29            r._lastTimeAt = t
30        }
31    }()
32    // ...
33}
34
35func NewProxier(...) {
36    // ...
37    proxier := &Proxier{
38    // ...
39        ipGetter: &realIPGetter{nl: NewNetLinkHandle(isIPv6), _cacheTimeout: time.Minute * 15},
40    // ...
41}
42
43// ...

修复后效果#

重新抓取结果，

实际时间也符合预期，在HTTP接口处消耗较多，

监控面板上对比，

待优化

增加随机时间，避免集群全局变动
1.20 实现优化

部分业务内存占用问题#

ipvs 连接不均衡问题#

我的博客起源

搭建自己的 Go mod 仓库