记一次 OOM (Out of Memory)的调查

现象

我的 Openshift 3.11 集群近一段时间节点总是莫名其妙就挂掉了,并且是卡到整个节点系统 hung 住,没有完全死掉的节点的控制台有大量的 Out of memory: Kill 日志打印出来

oom

但是最奇怪的是,挂掉的节点在 ESXi 中活动内存占用并不高,但是 CPU 直接满载

cpu-full

开始调查

仔细回忆了一下,近期在集群上部署了一套 CSI (Container Storage Interface) 插件,基本上有了一个排查的大方向,应该是插件的内存泄漏了,但还是要找到实锤

首先在没死透的节点上挣扎一下看看能不能通过 top 命令看到信息,但是内核已经彻底 hung 死,尝试登陆的 bash 都被 kill

dead-vm

没有办法,只能重启一台机器看看 OOM Killer 的日志吧

OOM Killer 日志

我的 Openshift 3.11 集群的宿主机是 CentOS 7,所以 OOM Killer 的日志会被存储在 /var/log/messages 中,如果机器重启过的话,过往的日志会被存储在 /var/log/messages-{restart_date} 中,如 /var/log/messages-20201223

重启完机器,直接 less /var/log/messages-$(date +%Y%m%d),输入命令 /Out of memory 回车,找到第一个引起 OOM 的程序

1
Dec 15 13:47:22 master-01 kernel: Out of memory: Kill process 66909 (livenessprobe) score 1687 or sacrifice child

确实是 CSI driver 的一部分,这是一个用于探测 CSI driver 提供的 GRPC 存活工具,由 kubernetes-csi 特别兴趣小组提供

n 继续搜索下一个,连续搜索了多个之后都是由这个 livenessprobe 引起的 OOM Kill,那基本上问题就在这里了

通过图表验证

想起 Openshift 在部署的时候,一同部署了一个 Prometheus + Grafana 的监控套件

找到 livenessprobe 所在的 Pod

pod-metrics-dashboard

果然,短短的一个小时不到,已经吃了不下 200M 内存,而且这个内存占用曲线是一直递增的,基本可以断定是内存泄漏了

代码验证

代码仓库: https://github.com/kubernetes-csi/livenessprobe

因为用的是 spec 0.3 版本的 CSI,所以,这里用的是 release-0.4 分支的代码

cmd/main.go 里有这样一个方法

1
2
3
4
5
6
7
8
9
func getCSIConnection() (connection.CSIConnection, error) {
// Connect to CSI.
glog.Infof("Attempting to open a gRPC connection with: %s", *csiAddress)
csiConn, err := connection.NewConnection(*csiAddress, *connectionTimeout)
if err != nil {
return nil, err
}
return csiConn, nil
}

connection.NewConnection 是创建一条 GRPC 连接,这个方法被 chekcHealth 方法调用(汗,还有错别字)

1
2
3
4
5
func chekcHealth(w http.ResponseWriter, req *http.Request) {

glog.Infof("Request: %s from: %s\n", req.URL.Path, req.RemoteAddr)
csiConn, err := getCSIConnection()
...

而这个方法又被注册到了 /healthz 路由上,也就是说,kubelet 的健康检查每请求一次这个健康检查接口,就会开启一条新的 GRPC 连接,而在检查完毕之后并没有让这个 GRPC 连接成为单例亦或是直接关闭这条连接

GRPC 的链接如果不关闭的话,其中持有的 io.Reader 以及 io.Writer 实例对象就得不到释放,内存就得不到释放,从而随着健康检查的请求数量越来越多,最终导致 OOM

破案

案子破了,是由于 livenessprobe 的没有关闭持有的 GRPC 连接,并且错误的在 /healthz 健康检查路由中不断去创建新的连接导致了最终的 OOM

仔细阅读了一下代码,实际上在 pkg/connection.go 中已经实现了一个对象用于持有 GRPC 的连接,只是在 getCSIConnection() 方法中返回的并不是单例的 CSIConnection 对象,而是每次都去创建新的连接

这个 BUG 已经在 Master 分支上被修复了,但是因为 Openshift 3.11 是基于 Kubernetes 1.11 的所以只能使用 CSI spec v0.3,所以才碰上这个 BUG

反思

GRPCClientConn 最好是单例的,如果想要重新连接,也要记得关闭连接,和 http 标准库中的 ResponseBody 同理,如果不关将无法释放持有的 io 对象