问题描述
某接口调用参数为两个时间字符串,分别表示起始时间,并使用 Parse 方法解析为 time.Time 类型。
当参数中的结束时间存在与 layout 格式不匹配的情况时,返回 400 Bad Request:
该次报错返回后,短时间内多次用正确参数请求接口,皆返回 500;一段时间后再次用正确参数请求接口,正常返回 200。
问题分析
context deadline exceeded 是 API 层在 RPC 调用超时的情况下返回的报错信息,因此程序在 Service 层执行时由于某种错误,导致了超时问题。
首先分析传递错误参数造成的后果。
当输入日期不符合 layout 定义的时间格式时,尝试进行字符串到时间的转换:
layout := "2006-01-02"
str := "2022-8-1"
date, err := time.Parse(layout, str)
fmt.Println(date)
fmt.Println(err)
输出结果为:
0001-01-01 00:00:00 +0000 UTC
parsing time "2022-8-1" as "2006-01-02": cannot parse "8-1" as "01"
可以看到,对字符串的解析失败了,而该方法返回了一个时间零值。首先想到的是,结束日期变为时间零值,会导致按照日期范围查询数据的 sql 语句无法查询到正确结果,但并不会导致运行超时。
查看对应服务的容器日志:
发现 RPC 远端调用只有开始,没有结束,且节点发生了重启,代表之前执行的服务让节点挂掉了。
查看代码,发现有一段类似这样的代码:
queryDate := startDate
for queryDate != endDate{
data = append(data, queryDate)
queryDate = queryDate.AddDate(0, 0, 1)
}
存在以下问题:
- endDate 因解析失败取得时间零值,导致循环无法退出
- 在循环中存在 append 操作,无限循环导致内存占用无限增长
因此推测,该无限循环导致容器分配超过上限的内容,被 Kubernetes 自动重启了。
查看 Kubernetes 文档,有以下相关说明:
如果容器尝试分配的内存量超出约束值, 则 Linux 内核的内存不足处理子系统会被激活,并停止尝试分配内存的容器中的某个进程。 如果该进程在容器中 PID 为 1,而容器被标记为可重新启动,则 Kubernetes 会重新启动该容器。
在容器内执行top命令,可以看到服务执行进程的 PID 为 1。
在 Pod YAML 中可以查看容器状态,其中包含了容器的重启信息:
其中,restartCount 表示容器运行以来的重启次数,reason 表示容器被终止的原因,OOMKilled 表示容器因尝试使用超出其限制的内存量而被终止。
容器资源约束配置如下:
可以看到容器最多可以请求的内存为 512MB。
查看容器的工作资源负载监控:
该监控30秒记录一次,而从请求到达到容器重启的时间很短,大概率无法捕获到内存暴涨的瞬间。
为了延长内存占用的时间,在代码中增加了 time.Sleep,顺利捕获到了内存的变化,但不能保证其准确反映最高点情况。
图中最高点的内存占用尚未超过 512MB。考虑到切片的扩容机制,此时内存并不是单纯随着时间线性增长的,而是完成一次扩容后在一段时间内保持不变,直到容量用尽执行下一次扩容,因此图中的最高点仍然很有可能是真实的内存占用最高点。推测是当 append 操作继续执行,切片需要扩容时,容器整体申请的内存超过了 512MB,触发了 OOMKilled。