分析 Go time.After 引起内存暴增 OOM 问题

Posted 2021-07-15 qcrao

还没正式上班，朋友来个电话让我帮忙排查一个问题。说是用 golang 写的牛逼的调度服务出现了内存泄露问题，Go 内存在任务暴增的时候增长很诡异。

从上线部署起，只要上游任务一上量就 oom 了。大过年的只能靠 supervisord 来重启。

本来寻思回北京再说，但这货大呼 golang 不靠谱，有内存泄露问题，没有他的 c++ 和 python 靠谱。无语，看来这个忙要帮……按照我的经验来说，oom 基本是因为人为的一些边界没控制好引起的。

先是看了他的烂代码，一个 golang 代码让他写出了 python pep8 的风格。代码里很多业务的逻辑，很晕，这么盲看也看不出个什么东西。直接用 go tool pprof 分析 golang 函数内存申请情况。果然可以看到不断的创建 time.After 定时器。

搜索代码里发现只有一处在创建 time.After 定时器，跳转过去，果然是问题代码。

for 循环里的 select 有两个 case，一个是 被其他 goroutine 不断输入任务的 chan，另一个是 time.After 定时器。当 queue 有任务时，那么 time.After 不会在该 select 里唤醒。而且，for 循环每次 select 的时候，都会实例化一个个新的定时器。该定时器在 3 分钟后，才会被激活，但是激活后已经跟 select 无引用关系，被 GC 给清理掉。

换句话说，被遗弃的 time.After 定时任务还是在时间堆里面，定时任务未到期之前，是不会被 GC 清理的。

// xiaorui.cc

func useTimeAfter(queue <-chan string) {
    defer wg.Done()
    for Running {
        select {
        case _, ok := <-queue
            if !ok {
                return
            }
            ...
       case <-time.After(3 * time.Minute):
            return
        }
    }
}

我们可以在 golang 程序里打印输出 runtime.MemStats 数据。经过测试，在差不多 3 分钟后，golang 的 heapObjects 数减少了，heapObjects 减少意味着我们上面的说法是对的。

通过 prometheus 和 linux free -m 看到的内存依然很大，这是因为 golang 是有内存池的，GC 在标记清除后，不会立马把空闲的内存还给系统，而是等待 5 分钟后的 scvg 来释放内存。

下面的 grafna 显示内存释放的时间是 10 分钟，分析了下 GODEBUG gctrace =1 日志，激活定时器和强制 2 分钟的 GC 和第一次的 scvg 的时间碰巧错开了，导致第一次 scvg 没有释放内存。以前测试 channel、map 的内存回收时，也遇到过该问题。

既然已经知道 Go 内存暴增的问题是由于“不断的创建 time.After 对象”，那么我们可以使用 NewTimer 来做定时器，不需要每次都创建定时器对象。代码如下:

// xiaorui.cc

func useNewTimer(in <-chan string) {
    defer wg.Done()
    idleDuration := 3 * time.Minute
    idleDelay := time.NewTimer(idleDuration)
    defer idleDelay.Stop()

    for Running {
        idleDelay.Reset(idleDuration)

        select {
        case _, ok := <-in
            if !ok {
                return
            }

            // handle `s`
        case <-idleDelay.C:
            return
        }
    }
}

总结

有经验的 gopher 都知道，在 for 循环里不要使用 select + time.After 的组合，有坑。当遇到性能和内存 GC 问题时，都可以使用 golang tool pprof 来排查分析问题。