记一次 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