R·ex / Zeng


音游狗、安全狗、攻城狮、业余设计师、段子手、苦学日语的少年。 MUGer, hacker, developer, amateur UI designer, punster, Japanese learner.

Golang 内存泄漏排查之旅

“业务提了个线上问题,麻烦你看一下。”

自从我开始写 Golang 后端之后,可能是能力有限,我的服务总是会在意想不到的情况下变得异常,而我要做的事情就是解决这个问题。

这次出现的问题看起来是运营平台后端服务的内存泄漏,那就先从内存曲线开始看起吧。

突然暴增的曲线

Grafana 平台给出的曲线大概符合这样的特征:有 8 个突变点,每次突变都会让内存猛然上升接近 500 MB,上涨到逼近容器上限后,突然回落到 100 MB(因为容器崩溃重启了)。

静态检查尝试失败

结合突变的时间,我搜了一下审计日志,发现业务上传了 8 次 Excel。但由于具体的上传日志在容器崩溃的时候丢失了,我不得不使用社会工程学通过 PM 直接给业务团队发消息拿到 Excel 文件。

观察了一下,每个文件都有着 4w 条记录,解析完成后恰好占用了大约 500 MB 内存(是的,对于有着大量重复单元格的场景,Excel 的压缩率超级高,因此几 MB 的文件可以被解析出几百 MB)。但问题来了:为什么是每次上涨 500 MB,难道是用于存储解析结果的变量被挂到了全局或闭包里?然而查了一下似乎并没有。

使用 pprof 对比快照

如果静态分析看不出问题,就要祭出 Golang 最著名的分析工具——pprof 了。但我初来乍到,在 heap / allocs 两个页面中研究了好久,并没有发现有异常。最后搜到了 这篇文章,发现 pprof 可以对两个快照做 Diff!大概做法如下:

# 一开始先执行
$ curl -s http://127.0.0.1:6060/debug/pprof/heap > base.heap

# 过一段时间,等内存增长后再执行
$ curl -s http://127.0.0.1:6060/debug/pprof/heap > current.heap

# 比较两个快照的差异
$ go tool pprof --base base.heap current.heap

然后,通过 pprof 生成了一个 SVG,打开一看,也没有问题,甚至部分函数占用的内存变化是负数……我在自己的外星人上面运行服务,疯狂上传大文件,过了几分钟后内存也恢复到了之前的水平。

MADV_FREE 与 MADV_DONTNEED

经过一番 搜索,发现从 Golang 1.12 开始,会在 Linux >= 4.5 内核下默认使用 MADV_FREE 来向系统归还内存,而之前的模式是 MADV_DONTNEED。查阅了 Linux manual page 之后,我大概有了些了解:

  • MADV_DONTNEED 会在释放的时候告诉操作系统内核:我不再需要这块内存了。内核虽然会自行决定何时释放这块内存,但进程的 RSS 一定会立即下降。
  • MADV_FREE 标记过的内存,则会让内核在内存紧张时才释放。在释放之前依旧可以复用。

总的来说,新特性可以加快内存释放的速度,但会造成进程的 RSS 不会立刻下降。这应该是 Golang 的一些考量,但直觉告诉我这可能就是原因。

结合之前学过的一点操作系统基础,大概可以得出结论:按理说这些内存本应可以复用,但当服务运行一段时间后,其中一部分已经被复用了。当业务再次上传文件,服务尝试申请相同大小的内存块时,由于这块内存的可用区域不再满足需求,系统只能在另一个地方重新分配一块,这就造成了 RSS 的不断暴涨。

解决方式有几种:

  1. 考虑到运营类平台对 QPS 要求不高,可以设置 GODEBUG=madvdontneed=1,让闲置内存尽快被系统回收;
  2. 强制单次上传的最大数量为 1000 条,并在超限时添加提示“最多上传 1000 条,可以只上传需要新增或修改的数据”;
  3. 使用流式 Excel 解析库,避免一次性分配过大的内存。

不过,考虑到这个需求即将下线,且之后短期内不会再有这种量级的文件上传需求,因此优先级不高。最终我们没有做处理。

为了避免容器意外崩溃后日志丢失,我们做了个技术优化,将每次请求的日志保存到了文件服务,之后不管容器是否崩溃,都可以根据时间查到具体的开发日志,甚至上传的文件了。

有借无还再借溢出

“看这曲线,你这容器是不是有内存泄漏啊?”这次轮到 SRE 同事来找我了。

确实,SRE 给的图随便扫一眼就知道是内存泄漏,只不过这次的曲线跟上次相比有个很大的不同——以一个较为缓慢的速度增长。看起来像是每次请求都会保留一些小变量。

这次出问题的服务是我们的数据上报服务。在没有明确头绪的情况下,我又打开了 pprof 如法炮制。

对 Gin 的怀疑

这次内存占用的大头变成了 Golang 的 gzip 包。在我印象中,只有一个地方使用了 gzip:Gin 的请求压缩,也就意味着可能存在没有被关闭的 Reader / Writer。于是我跑去 Gin 的 gzip 包里面找原因,发现它用了一个 Pool,每次先从里面取一个实例,再设置一些 Gin Response Header,最后把实例的 Writer 接到了 Gin Context。在 #L57 行时执行了 defer gz.Close() 并把实例归还给 Pool 了,看起来有借有还有关闭,不会造成内存泄漏。

既然 Gin 的 gzip 使用没有问题,难道是 Golang 自己的 gzip 包出问题了?我点进了 Close 函数,发现了 这段代码

func (z *Writer) Close() error {
    // ...
    if !z.wroteHeader {
        z.Write(nil)
        if z.err != nil {
            return z.err
        }
    }
    z.err = z.compressor.Close()
    // ...
}

只要 Writer 出了问题就不会 Close,肯定是因为这里导致的!我在 return 这里打了断点,果然,z.err 是这样的:

http: request method or response status code does not allow body

根据错误内容看了一下,发现请求方法是 OPTIONS(上报服务肯定会有跨域问题),确实不应该有 Body。

我们为了支持跨域,使用了 gin-contrib/cors 中间件,回想到它的原理是发现 OPTIONS 请求后,经过白名单过滤,直接返回结果,而不是继续往下 c.Next()。那么为什么不生效呢?

看了一下注册中间件的代码,发现我们把 gzip 的中间件放到了第一位,随后才是 CORS 中间件……换一下顺序就解决了。

错误就能不还了吗?

那为什么在出错的时候 Golang 没有自动关闭 compressor 呢?看了一下 Golang gzip 包的 Write 方法后,得出了一个原因:多次调用 Write 方法时,只要第一次成功,就会有一个打开的 compressor,如果之后出现了错误,Golang 不知道开发者希望如何处理,因此不擅自做决定。如果开发者此时:

  • 希望忽略错误继续往里写入,可以调用 gz.Reset(newWriter) 方法,这会保留 compressorlevel,剩下的字段全部重置;
  • 希望就此打住,可以按照 Example 中的写法直接 panic,也可以先 Reset 之后再 Close

值得一提的是,Golang 推荐开发者尽可能使用 Reset 复用 gzip 实例,这也许是 Gin gzip 中间件使用了 Pool 的原因。

孤独等待的计时器

随着数据上报服务的请求量逐渐上涨,SRE 又来找我了,这次依旧是内存泄漏问题,并且内存曲线也是稳定上升。但这次有点不一样的是,只有 Live 环境出现了这个情况,而 Test 环境完全没问题。

不留痕迹的 goroutine 泄露

经历过前面几次内存溢出的经验,我总结出了一点:拯救世界,请用 pprof Heap Diff。然而这一次,银弹失灵了,我没有从 Heap Diff 中发现任何问题……数据上报服务应该是一个很简单的服务,不应该有太大的问题才对的。

但是似乎 Golang 分析内存问题也没有其它工具,我不得不重新审视 pprof 提供的功能。在首页,我发现了当前有数十万个 goroutine 在运行。这是我之前一直没有考虑过的点——goroutine 泄漏。

重新回到正常的 Heap Profile 界面,果然发现了一大堆 goroutine 的堆栈,它们不约而同地指向了同一个函数,看起来结论已经很明显了。我点进这个函数看了一下,才知道为什么 Diff 没有任何效果:这个函数自身没有定义任何新的变量,也没有生成任何新的字面量,在 Heap 中当然不会留下任何痕迹。

计时器不能随便停啊

这个函数的功能是批量提交:之前每次接收到的数据会先被放在一个队列中,然后调用这个函数设定一个计时器(如果已有计时器则直接 return),十秒之后把队列中的数据发送到一个批量接口中。但为了保证队列中的内容不会太多,只要超过了 5000 条数据,就会新起一个队列替换当前队列,然后直接将替换掉的队列中的数据批量提交。在 JavaScript 里面,这个功能很简单:

let q: ReportData[] = [];
let timerId = 0;

// 接收单个数据,若数据过多则直接提交,否则最多 10s 后提交
const pushBack = (data: ReportData) => {
    q.push(data);
    if (q.length > 5000) {
        flush();
    } else {
        scheduleFlush();
    }
    return data;
};

// 设定计时器
const scheduleFlush = () => {
    if (timerId) return;
    timerId = setTimeout(() => flush(), 10 * 1000);
};

// 真正的提交操作,会清理计时器,并创建一个新队列
const flush = () => {
    setTimeout(() => commit(q));
    clearTimeout(timerId);
    q = [];
};

但是到了 Golang,计时器要用到 time.Ticker,于是我的代码成了这样:

func (q *MemQueue) PushBack(ele interface{}) interface{} {
    q.mu.Lock()
    defer q.mu.Unlock()

    q.queue[q.index].PushBack(ele)
    q.len++
    if q.len >= 5000 {
        q.flush()
    } else {
        q.scheduleFlush()
    }

    return ele
}

func (q *MemQueue) scheduleFlush() {
    if q.ticker != nil {
        return
    }
    d := time.Duration(10 * int64(time.Second))
    q.ticker = time.NewTicker(d)
    go func() {
        for {
            if q.ticker == nil {
                return
            }
            <-q.ticker.C
            q.flush()
        }
    }()
}

func (q *MemQueue) flush() {
    go commit(q.queue[q.index])
    q.index = 1 - q.index
    q.len = 0
    q.ticker.Stop()
    q.ticker = nil
    q.queue[q.index] = list.New()
}

之前 Stack 中不约而同指向的位置,就是 scheduleFlush 中的那个 goroutine,它卡在 <-q.ticker.C 这一步,意味着计时器已经停止了。确实,当数据超过 5000 条时会直接调用 flush 函数,在停止计时器后,虽然会将 ticker 置空,但由于 <-q.ticker.C 再也收不到数据,因此并不会进行下一轮循环。等到下一次数据被推过来时,又会在 scheduleFlush 中启动一个新的 goroutine。

让 Channel 来救场

知道了原因,简单搜了一下,发现了 这个回答,解决方法也就有了:利用一个额外的 Channel 让循环继续下去。

go func() {
    for {
        if q.ticker == nil {
            return
        }
        select {
        case <-q.forceStop:
            return
        case <-q.ticker.C:
            q.flush()
            return
        }
    }
}()

// 在想停止计时器的地方
q.forceStop <- true
q.ticker.Stop()
q.ticker = nil

部署之后发现问题解决。那为什么只有 Live 环境会出问题,而 Test 环境没问题呢?因为 flush 函数会在两个地方被调用到——scheduleFlushPushBack。问题出在从 PushBack 直接调用 flush 的时候,而这个条件是队列需要在 10s 内积攒 5000 条数据,Test 环境的 QPS 没有高到这个程度,所以没有出现这个问题。

溢出屏幕的 SRE 告警

在那之后的某一天,我直接被 SRE 拉到了他们的告警群里。群里最新的消息是:[error] 11:52 AM ssc k8s pod mem alert 达到 92.60%,在这之前还有五条消息报的是相同的问题。

我(看了一眼 K8S 面板):“已知是内存泄漏问题,求一个大佬先帮忙临时重启一下,我们下次发版后解决。”

似乎不小心给自己立了个 Flag,因为距离下次发版只有两天了。这次的项目,是本文最开始提到的运营平台后端服务。

GC 解决不了的问题

这次的内存曲线看起来跟一开始的也很类似,会有突然的暴增。我本来以为是:部门发展了一年,请求量大了,业务场景也变多了,可能这次真的需要定时强制释放内存了。于是加了个定时器:

func freeMemory(r *registry.Registry) {
    debug.FreeOSMemory()
    r.BasicLogger.Info("free-memory", "Free memory successful")
}

c := cron.New()
c.AddJob("@every 10m", &freeMemoryJob{
    f: freeMemory,
})
c.Start()

然后发现曲线长成了这样:

内存泄漏时的 K8S 监控曲线

只能用一句话来表达此时的感受:气哭.jpg。当时后端出身的老板刚好经过我工位,希望他没有看到这张图吧。

图中之所以每小时有一个峰值,因为我们有一个按小时执行的计划任务,可能会占用一些内存;之所以后来下降了好多,是因为我重新部署了……

全局 map 要慎用

行吧,应该还是有什么小型变量忘了释放。我故技重施,打开了 pprof。

pprof 绘制出来的调用关系图

凭借我对自己代码的了解,我知道这一部分的需求是什么:就是在解决一开始的问题时提出的技术优化——将开发日志保存到文件服务。对于一个请求,如何收集贯穿整个服务的开发日志呢?一个比较容易想到的方法是设置一个全局变量 map[string][]string,也就是 Trace ID 到该请求的日志列表的映射。在请求的过程中可以随时往里面添加日志,请求结束后通过中间件将日志列表中的内容保存到文件服务,然后删除掉这个 Trace ID 对应的数据。

一切看起来天衣无缝——每个请求不管过程和结果如何,最终 map 中的内容一定会被删除,但这个曲线看起来就跟没有被删除一样。以前之所以没有出过这个问题,是因为以前打的日志量比较少,内存增长不明显。现在日志量大了,就出现了这个问题。

迫于 SRE 大佬的压力,我通过不断将 golang map delete memory leak 这几个词语排列组合搜索,也去看了一下 map 的实现,参考了 这篇文章,发现了这样一个问题:Golang 的 map 在删除 Key 的时候,只会把 Key 标记为 empty,而不是彻底删除,这样在下一次插入相同的 Key 时就可以节约一些时间。考虑到 map 用的是哈希表,经常的扩缩容确实对性能有影响,这种设计看起来还算合理。

但是我这个使用场景有个严重的问题:我的 Key 是 Trace ID,也就意味着几乎没有重复的可能,几乎所有的值都会被保留下来。以前的 QPS 很低,日志量也少,于是这个问题没有那么明显;现在有些计划任务动辄上千条日志,这个问题就被放大了。

如何解决呢?其实也很简单,只要去掉全局的 map,使用中间件在每一个 Gin Context 中生成一个新的 logger,最后只上传这个 logger 的内容就可以了。此外,由于在这段时间里,公司的 Infra 团队自研了一套日志平台,我也毫不犹豫地接了进去,之后日志就不用保存到文件服务了。

运行了一段时间,看监控可以发现,内存泄漏已经解决了;用 pprof Diff 了一下,发现已经没有被标红的函数,甚至有一些函数被标绿了,意味着这些函数占用的内存下降了。

可以看出,内存泄漏已经解决了

之所以一开始内存还有上涨的迹象,是因为这个服务为了效率而缓存了访问的用户数据。数据量最多只有几万,对内存没有什么压力。

小结

经过这一段时间与内存泄漏的斗争被完虐,我发现自己似乎把常见的内存泄漏问题都遇到了一遍,也算是积累了一些经验。我不确定现在的项目是否还有潜在的内存泄漏风险,但我已经有足够的信心来解决不管是未知还是已知的问题了。

版权声明:除文章开头有特殊声明的情况外,所有文章均可在遵从 CC BY 4.0 协议的情况下转载。
上一篇: TypeScript 小技巧:校验 i18n 参数
下一篇: 没有了

这是我们共同度过的

第 2208 天