以下语言可用： 简体中文 正體中文 English
“业务提了个线上问题，麻烦你看一下。”
自从我开始写 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 的不断暴涨。
解决方式有几种：
- 考虑到运营类平台对 QPS 要求不高，可以设置
GODEBUG=madvdontneed=1，让闲置内存尽快被系统回收； - 强制单次上传的最大数量为 1000 条，并在超限时添加提示“最多上传 1000 条，可以只上传需要新增或修改的数据”；
- 使用流式 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)方法，这会保留compressor和level，剩下的字段全部重置； - 希望就此打住，可以按照 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 函数会在两个地方被调用到——scheduleFlush 和 PushBack。问题出在从 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()然后发现曲线长成了这样：
只能用一句话来表达此时的感受：气哭.jpg。当时后端出身的老板刚好经过我工位，希望他没有看到这张图吧。
图中之所以每小时有一个峰值，因为我们有一个按小时执行的计划任务，可能会占用一些内存；之所以后来下降了好多，是因为我重新部署了……
全局 map 要慎用
行吧，应该还是有什么小型变量忘了释放。我故技重施，打开了 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 了一下，发现已经没有被标红的函数，甚至有一些函数被标绿了，意味着这些函数占用的内存下降了。
之所以一开始内存还有上涨的迹象，是因为这个服务为了效率而缓存了访问的用户数据。数据量最多只有几万，对内存没有什么压力。
小结
经过这一段时间与内存泄漏的斗争被完虐，我发现自己似乎把常见的内存泄漏问题都遇到了一遍，也算是积累了一些经验。我不确定现在的项目是否还有潜在的内存泄漏风险，但我已经有足够的信心来解决不管是未知还是已知的问题了。