虽然是开发工作，在保障稳定性中，有时候会有很多重要单不是特别紧急的问题。我一般都是集中一起安排时间排查，这里做一些记录和汇总，_不具备任何系统性的知识内容。_ > 每段都是独立补充，所以时间表述上可能与文章不一致。 ### 容器关闭失败自从隔壁组的服务治理上线以来，一直就收到集群内容器关闭失败的报警。不过一直也没人关注，不实际影响业务。但是影响宿机器的资源使用。同时这么多的报警也影响运维的响应效率。下午正好有空就抽空进行了一次问题排查。 1. 情况1 登录上机器，找到找到envoy sidecar的进程。先看下调用栈， ```bash [root@wc-testk8s-0-103 cgroup]# cat /proc/291967/stack [] do_wait+0x1d7/0x250 [] kernel_wait4+0x89/0x140 [] SYSC_wait4+0x86/0x90 [] SyS_wait4+0xe/0x10 [] zap_pid_ns_processes+0x103/0x1a0 [] do_exit+0xb29/0xbe0 [] do_group_exit+0x3f/0xb0 [] get_signal+0x166/0x780 [] do_signal+0x37/0x6a0 [] exit_to_usermode_loop+0x5b/0xc5 [] do_syscall_64+0xe7/0x120 [] entry_SYSCALL_64_after_hwframe+0x3d/0xa2 [] 0xffffffffffffffff ``` `zap_pid_ns_processes`应该是等待 pid namespace 下其他进程的退出。我找到另一个（子）进程`362091`，同样地看看stack, ```bash [root@wc-testk8s-0-103 cgroup]# cat /proc/362091/stack [] call_rwsem_down_read_failed+0x18/0x30 [] iterate_supers+0xa2/0x110 [] sys_sync+0x44/0xb0 [] do_syscall_64+0x66/0x120 [] 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. 情况2 首先先找到容器ID，并查看 dockerd 的日志 `journalctl -u docker` 。发现下面日志， ```bash 6 10 16:09:15k8s-0-176 dockerd[1751]: time="2021-06-10T16:09:15.458629778+08:00" level=info msg=" Container 10f0451e1345 failed to exit within 10 seconds of kill - trying direct SIGKILL" 6 10 16:11:06k8s-0-176 dockerd[1751]: time="2021-06-10T16:11:06.286046073+08:00" level=info msg=" Container 10f0451e1345f5028f636e2b09c9f8204e55a01f5f09f2e57de3c17d3f93f492 failed to exit within 30 seconds of signal 15 - using the force" 6 10 16:11:16k8s-0-176 dockerd[1751]: time="2021-06-10T16:11:16.301226981+08:00" level=info msg=" Container 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， ```bash [] do_wait+0x1d7/0x250 [] kernel_wait4+0x89/0x140 [] SYSC_wait4+0x86/0x90 [] SyS_wait4+0xe/0x10 [] zap_pid_ns_processes+0x103/0x1a0 [] do_exit+0xb29/0xbe0 [] do_group_exit+0x3f/0xb0 [] get_signal+0x166/0x780 [] do_signal+0x37/0x6a0 [] exit_to_usermode_loop+0x5b/0xc5 [] do_syscall_64+0xe7/0x120 [] entry_SYSCALL_64_after_hwframe+0x3d/0xa2 [] 0xffffffffffffffff ``` 又是等待命名空间下的进程退出。继续找到相关的进程查看stack， ```bash [] __ceph_do_pending_vmtruncate+0x4e/0x260 [ceph] [] __ceph_setattr+0x665/0x9b0 [ceph] [] ceph_setattr+0x4c/0x80 [ceph] [] notify_change+0x2f4/0x440 [] do_truncate+0x75/0xc0 [] path_openat+0xb33/0x1480 [] do_filp_open+0x91/0x100 [] do_sys_open+0x124/0x210 [] SyS_open+0x1e/0x20 [] do_syscall_64+0x66/0x120 [] entry_SYSCALL_64_after_hwframe+0x3d/0xa2 [] 0xffffffffffffffff ``` 看上去和ceph相关，查看 ceph的代码，这个函数应该是需要链接网络的，所以一直卡在这里。我们查看进程的命名空间， ```bash dr-x--x--x 2 root root 0 6 11 10:08 . dr-xr-xr-x 9 root root 0 6 9 17:21 .. lrwxrwxrwx 1 root root 0 6 11 10:08 cgroup lrwxrwxrwx 1 root root 0 6 11 10:08 ipc lrwxrwxrwx 1 root root 0 6 11 10:08 mnt lrwxrwxrwx 1 root root 0 6 11 10:08 net lrwxrwxrwx 1 root root 0 6 11 10:08 pid -> pid:[4026536204] lrwxrwxrwx 1 root root 0 6 11 10:08 pid_for_children lrwxrwxrwx 1 root root 0 6 11 10:08 user -> user:[4026531837] lrwxrwxrwx 1 root root 0 6 11 10:08 uts ``` 发现，网络命名空间已经没有了。那么，问题会不会是出现在这里呢？ ### apiserver 内存问题听运维说这是一个困扰集群A很久的问题。 master节点上内存被apiserver占掉10G+。而且还有其他自研发controller会OOM。这也没什么好说的，先pprof抓处理看把。默认是打开调试的。 ```bash kubectl proxy go tool pprof "https://127.0.0.1:8001/debug/pprof/heap?seconds=120" --mem go tool pprof --http :9090 xxx.pb.gz ``` ![](https://i.imgur.com/BpRzRfh.png) 已经很明显了，大部分都是RS的反序列化操作。这是不应该的，RS又没有其他资源使用频繁。那么只有一个可能，那就是RS泄漏了。要么是垃圾回收有问题，要么是版本设置错了。先手动删除一下， ```bash kubectl get rs -A|awk '{print $1 " " $2 " " $3 $4 $5}'|grep "000$" > rs.list.0 while read p; do ns=`echo $p|awk '{print $1}'` name=`echo $p|awk '{print $2}'` kubectl delete rs -n $ns $name & done < 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的关系了。幸好，运维没有杀掉进程，先看看进程的调用栈， ```bash [] wait_woken+0x6e/0x90 [] n_tty_read+0x3e4/0x920 [] tty_read+0x92/0xf0 [] __vfs_read+0x37/0x140 [] vfs_read+0x8c/0x130 [] SyS_read+0x55/0xc0 [] do_syscall_64+0x66/0x120 [] entry_SYSCALL_64_after_hwframe+0x3d/0xa2 [] 0xffffffffffffffff ``` `tty_read`，看上去没什么异常，应该是正常的等待标准输入。本来以为是卡在`ADD`或者`CHECK`的COMMAND上的。最后在开发环境测试发现，其他命令正常，只有`VERSION`这一个会卡住。这个命令完全是cni自己实现的，难道是cni库的bug吗？看下`go.mod`中cni的版本是`0.6.0`。直接升级到最新版本`0.8.1`并重新适配一下， ```golang skel.PluginMain(cmdAdd, cmdDel, func(*skel.CmdArgs) error { return nil }, version.All, "") ``` 编译后运行， ```bash (base) thsipam git:(leak) CNI_COMMAND=VERSION ./xxipam {"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)。这里自然就会一直堵塞，无法读取到内容。看下新版本，加了一下判断， ```golang if cmd == "VERSION" { t.Stdin = bytes.NewReader(nil) } ``` 这个修复首次出现在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` ![](https://i.imgur.com/HWF5oG9.png) ![](https://i.imgur.com/7YS6zHR.png) 看上去很明显了：`realIpGetter.NodeIPs`这个占用太多的时间。 #### 解决方案 1. 确认NodeIPs函数无需频繁调用后，进行结果的缓存 2. 增加缓存结果，缓存时间为15分钟，对于机器IP变动来说，这足够使用 ```golang // realIPGetter is a real NodeIP handler, it implements IPGetter. type realIPGetter struct { // nl is a handle for revoking netlink interface nl NetLinkHandle // TODO: use x.Cache utils _lastResult []net.IP _lastReserr error _lastTimeAt time.Time _cacheTimeout time.Duration _lock sync.Mutex } func (r *realIPGetter) NodeIPs() (ips []net.IP, err error) { r._lock.Lock() defer r._lock.Unlock() // get data from cache first if no error and not expiry t := time.Now() expiryAt := r._lastTimeAt.Add(r._cacheTimeout) if r._lastReserr == nil && t.Before(expiryAt) { klog.V(4).Infof("NodeIPs call result return from cache (expired in %v): %v", t.Sub(expiryAt), r._lastResult) return r._lastResult, nil } defer func(){ r._lastReserr = err if err == nil { klog.V(4).Infof("NodeIPs call directlly, and cache the result: %v", ips) r._lastResult = ips r._lastTimeAt = t } }() // ... } func NewProxier(...) { // ... proxier := &Proxier{ // ... ipGetter: &realIPGetter{nl: NewNetLinkHandle(isIPv6), _cacheTimeout: time.Minute * 15}, // ... } // ... ``` #### 修复后效果重新抓取结果， ![](https://i.imgur.com/iX8shRV.png) 实际时间也符合预期，在HTTP接口处消耗较多， ![](https://i.imgur.com/x4nWJPQ.png) 监控面板上对比， ![](https://i.imgur.com/9RbD2yd.png) 待优化 - 增加随机时间，避免集群全局变动 - 1.20 实现优化 ### 部分业务内存占用问题 ### ipvs 连接不均衡问题

标签: Kubernetes