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

前言:

还没正式上班,朋友来个电话让我帮忙排查一个问题。说是用golang写的牛逼的调度服务出现了内存泄露问题,go内存在任务暴增的时候增长很诡异。从上线部署起,只要上游任务一上量就oom了。大过年的只能靠supervisord来重启。
本来寻思回北京再说,但这货大呼golang不靠谱,有内存泄露问题,没有他的c++和python靠谱。 无语,看来这个忙要帮…. 按照我的经验来说,oom基本是因为人为的一些边界没控制好引起的。

该文章后续仍在不断的更新修改中, 请移步到原文地 http://xiaorui.cc/?p=5745

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

搜索代码里发现只有一处在创建time.After定时器,跳转过去,果然是问题代码。
for循环里的select有两个case,一个是 被其他golang不断输入任务的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 := <-:
            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的组合,有坑。当使用golang过程中,遇到性能和内存gc问题,都可以使用golang tool pprof来排查分析问题。


大家觉得文章对你有些作用! 如果想赏钱,可以用微信扫描下面的二维码,感谢!
另外再次标注博客原地址  xiaorui.cc