记一次线上GoLang项目OOM排查过程

在Go语言中使用了gin web框架，我们有一个接口是文件下载服务，用户下载超过100M文件就会OOM导致重启服务,本文主要记录通过Golang内置的pprof服务来排查OOM问题的过程。

问题现象

网站一功能包含文件下载功能，用户通过接口下载超过100M的文件就下载不全下载到30M～50M左右浏览器就显示下载完成。发现测试环境并没有问题，通过对比K8S部署文件,发现只有Memory Limit测试环境比较高，当时猜测Golang本身不像Java应该不是很消耗内存才对。

开始还怀疑是NGINX连接中断的问题，因为我们网站的前端和K8S网关(Ingress Controller)都使用了Nginx了，是哪个环节出问题了吗？通过添加一些timeout超时参数和使用NodePort直接访问后端服务确定就是后端服务问题。

因为测试环境代码迭代比生产快很多，难道是代码Bug生产上未修复？排查了一遍代码也没有看出啥问题，最后尝试在测试环境将内存降低也重现了这个问题，排除测试和生产代码不一致问题。

通过Prometheus监控也没看出内存泄漏问题。（最终判定应该是监控不灵敏未检测到程序就重启完成了，我们监控系统的采集周期是15s）

通过Kubectl describe 查看Pod状态发现确实有重启，Last Stated 就是OOMKilled。

于是尝试将生产服务的内存加大，确实能暂时缓解。于是开始了下面的排查流程。

代码定位，尝试修复失败

核心代码：

func DownloadPodLogs(c *gin.Context) {
	host := c.Query("host")
	if host == "" {
		c.JSON(http.StatusBadRequest, gin.H{"error": "没有Host参数"})
		return
	}
	u, _ := url.ParseRequestURI(fmt.Sprintf("http://%s:%s/api/logs/download", host, daemonServicePort))
	data := url.Values{}
	data.Set("namespace", c.Param("namespace"))
	data.Set("app", c.Param("app"))
	data.Set("pod", c.Param("pod"))
	data.Set("path", c.Param("filename"))
	fmt.Println(data.Encode())
	u.RawQuery = data.Encode()
	res, err := http.Get(u.String())
	if err != nil {
		c.JSON(http.StatusBadRequest, gin.H{"error": err.Error()})
		return
	}

	defer res.Body.Close()

	c.Status(res.StatusCode)
	c.Header("Content-Type", "application/force-download")
	c.Header("Content-Disposition", fmt.Sprintf("attachment;filename*=utf-8''%s", c.Param("filename")))
	_, err = io.Copy(c.Writer, res.Body)

	if err != nil {
		log.Panic(err)
	}
	c.Writer.Flush()
}

其实这块代码并没有问题，根据io.Copy的实现,此Copy函数实现将src拷贝到dst，直到在src上读取EOF或错误发生。

func Copy(dst Writer, src Reader) (written int64, err error) {
	return copyBuffer(dst, src, nil)
}

copyBuffer代码中可以发现，buf==nil时，会申请一个3M的缓冲区，然后for循环从src中读取内容，每次读取完成后写入到dst。

// copyBuffer is the actual implementation of Copy and CopyBuffer.
// if buf is nil, one is allocated.
func copyBuffer(dst Writer, src Reader, buf []byte) (written int64, err error) {
	// If the reader has a WriteTo method, use it to do the copy.
	// Avoids an allocation and a copy.
	if wt, ok := src.(WriterTo); ok {
		return wt.WriteTo(dst)
	}
	// Similarly, if the writer has a ReadFrom method, use it to do the copy.
	if rt, ok := dst.(ReaderFrom); ok {
		return rt.ReadFrom(src)
	}
	if buf == nil {
		size := 32 * 1024
		if l, ok := src.(*LimitedReader); ok && int64(size) > l.N {
			if l.N < 1 {
				size = 1
			} else {
				size = int(l.N)
			}
		}
		buf = make([]byte, size)
	}
	for {
		nr, er := src.Read(buf)
		if nr > 0 {
			nw, ew := dst.Write(buf[0:nr])
			if nw < 0 || nr < nw {
				nw = 0
				if ew == nil {
					ew = errInvalidWrite
				}
			}
			written += int64(nw)
			if ew != nil {
				err = ew
				break
			}
			if nr != nw {
				err = ErrShortWrite
				break
			}
		}
		if er != nil {
			if er != EOF {
				err = er
			}
			break
		}
	}
	return written, err
}

所以这块应该是没有问题，但是我还是尝试修改了两个版本：
第一个版本：不用io.Copy改用类似Copy函数底层实现

	buf := make([]byte, 32*1024) // 32 KB buffer
	for {
		n, err := res.Body.Read(buf)
		if n > 0 {
			if _, writeErr := c.Writer.Write(buf[:n]); writeErr != nil {
				log.Printf("Write error: %v", writeErr)
				return
			}
			c.Writer.Flush() // 强制立即发送
		}
		if err != nil {
			if err != io.EOF {
				log.Printf("Read error: %v", err)
			}
			break
		}
	}

第二个版本：改用gin的Stream流

	buf := make([]byte, 32*1024) // 32 KB buffer
	c.Stream(func(w io.Writer) bool {
		n, err := res.Body.Read(buf)
		if n > 0 {
			_, writeErr := w.Write(buf[:n])
			if writeErr != nil {
				log.Printf("Write error: %v", writeErr)
				return false
			}
		}
		if err != nil {
			if err != io.EOF {
				log.Printf("Read error: %v", err)
			}
			return false
		}
		return n > 0
	})

以上三个版本的代码都能下载文件，但是都不能解决OOM问题。

问题依旧，只能依靠pprof来排查了。

pprof使用，找出真凶

pprof介绍

是什么：
pprof 是用于可视化和分析性能分析数据的工具

pprof 以 profile.proto 读取分析样本的集合，并生成报告以可视化并帮助分析数据（支持文本和图形报告）

profile.proto 是一个 Protocol Buffer v3 的描述文件，它描述了一组 callstack 和 symbolization 信息， 作用是表示统计分析的一组采样的调用栈，是很常见的 stacktrace 配置文件格式

支持什么使用模式：
Report generation：报告生成
Interactive terminal use：交互式终端使用
Web interface：Web 界面
可以做什么：
CPU Profiling：CPU 分析，按照一定的频率采集所监听的应用程序 CPU（含寄存器）的使用情况，可确定应用程序在主动消耗 CPU 周期时花费时间的位置
Memory Profiling：内存分析，在应用程序进行堆分配时记录堆栈跟踪，用于监视当前和历史内存使用情况，以及检查内存泄漏
Block Profiling：阻塞分析，记录 goroutine 阻塞等待同步（包括定时器通道）的位置
Mutex Profiling：互斥锁分析，报告互斥锁的竞争情况

代码注入pprof

在与main.go文件相同位置写一个pprof.go文件，在打包时带上tags(go build --tags pprof ....)程序启动后就可以通过http://127.0.0.1:6060/debug/pprof/端口直接查看运行时资源情况。参考：https://pkg.go.dev/runtime/pprof

//go:build pprof
// +build pprof

package main

import (
	"fmt"
	"net/http"
	_ "net/http/pprof"
)

func init() {
	go pprofServer()
}

func pprofServer() {
	ip := "0.0.0.0:6060"
	if err := http.ListenAndServe(ip, nil); err != nil {
		fmt.Printf("start pprof failed on %s\n", ip)
	}
}

通过Web界面分析

直接在浏览器访问http://127.0.0.1:6060/debug/pprof/ 界面
查看当前总览：

/debug/pprof/
profiles:
0    block
5    goroutine
3    heap
0    mutex
9    threadcreate
full goroutine stack dump

这个页面中有许多子页面，咱们继续深究下去，看看可以得到什么？

cpu（CPU Profiling）: $HOST/debug/pprof/profile，\mathrm{默}\mathrm{认}\mathrm{进}\mathrm{行}30s\mathrm{的}CPUProfiling，\mathrm{得}\mathrm{到}\mathrm{一}\mathrm{个}\mathrm{分}\mathrm{析}\mathrm{用}\mathrm{的}profile\mathrm{文}\mathrm{件}block（BlockProfiling）：$HOST/debug/pprof/block，查看导致阻塞同步的堆栈跟踪
goroutine：$HOST/debug/pprof/goroutine，查看当前所有运行的 goroutines 堆栈跟踪
heap（Memory Profiling）: $HOST/debug/pprof/heap，\mathrm{查}\mathrm{看}\mathrm{活}\mathrm{动}\mathrm{对}\mathrm{象}\mathrm{的}\mathrm{内}\mathrm{存}\mathrm{分}\mathrm{配}\mathrm{情}\mathrm{况}mutex（MutexProfiling）：$HOST/debug/pprof/mutex，查看导致互斥锁的竞争持有者的堆栈跟踪
threadcreate：$HOST/debug/pprof/threadcreate，查看创建新 OS 线程的堆栈跟踪

通过交互式终端使用

由于我们是像观察内存，所以重点看第一个

（1）go tool pprof http://localhost:6060/debug/pprof/heap?seconds=60

执行该命令后，需等待 60 秒（可调整 seconds 的值），pprof 会进行 内存记录。结束后将默认进入 pprof 的交互式命令模式，可以对分析的结果进行查看或导出。
比如使用top命令查看前10。
具体可执行 pprof help 查看命令说明

$ go tool pprof http://10.5.x.x:30596/debug/pprof/heap?seconds=60
Fetching profile over HTTP from http://10.5.x.x:30596/debug/pprof/heap?seconds=60
Saved profile in /home/ycyin/pprof/pprof.main.alloc_objects.alloc_space.inuse_objects.inuse_space.001.pb.gz
File: main
Type: inuse_space
Time: Dec 4, 2024 at 2:27pm (CST)
Duration: 60s, Total samples = 288.28MB 
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 280.73MB, 97.38% of 288.28MB total
Dropped 3 nodes (cum <= 1.44MB)
Showing top 10 nodes out of 26
      flat  flat%   sum%        cum   cum%
  284.26MB 98.60% 98.60%   284.26MB 98.60%  github.com/gin-contrib/cache.(*cachedWriter).Write
   -3.53MB  1.22% 97.38%    -3.53MB  1.22%  compress/flate.NewWriter
         0     0% 97.38%    -3.53MB  1.22%  bufio.(*Writer).Flush
         0     0% 97.38%    -3.53MB  1.22%  compress/gzip.(*Writer).Write
         0     0% 97.38%   284.76MB 98.78%  github.com/gin-contrib/cache.CachePage.func1
         0     0% 97.38%   281.23MB 97.55%  github.com/gin-gonic/gin.(*Context).Next (inline)
         0     0% 97.38%   284.26MB 98.60%  github.com/gin-gonic/gin.(*Context).Stream
         0     0% 97.38%   281.23MB 97.55%  github.com/gin-gonic/gin.(*Engine).ServeHTTP
         0     0% 97.38%   281.23MB 97.55%  github.com/gin-gonic/gin.(*Engine).handleHTTPRequest
         0     0% 97.38%   281.23MB 97.55%  github.com/gin-gonic/gin.CustomRecoveryWithWriter.func1

-inuse_space：分析应用程序的常驻内存占用情况
-alloc_objects：分析应用程序的内存临时分配情况

（2）go tool pprof http://localhost:6060/debug/pprof/profile

（3） go tool pprof http://localhost:6060/debug/pprof/block

（4） go tool pprof http://localhost:6060/debug/pprof/mutex

pprof可视化界面

上面通过命令行比较麻烦，可以使用pprof结合graphviz带来的可视化服务，是问题定位能够更加清晰。（首先需要下载安装graphviz）

先通过Curl下载pprof文件到本地，然后进入web界面

$ curl -s http://172.26.29.58:30596/debug/pprof/heap?seconds=60 > heap.out

第一种方式使用go tool pprof heap.out然后输入web会打开浏览器展示调用图

$ go tool pprof heap.out
File: main
Type: inuse_space
Time: Dec 4, 2024 at 3:02pm (CST)
Duration: 60s, Total samples = 288.28MB 
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) web

第二种方式使用直接本地启动一个web服务

$ go tool pprof -http=:8080 cpu.prof
Serving web UI on http://localhost:8080

第二种方式可以以多个角度来分析:
VIEW:
Top：和top命令相同，将函数按资源使用进行排名

Graph：如图的函数调用逻辑图以及节点使用

Flame Graph：火焰图，资源使用按从大到小排列，点击可看详细信息

Peek：打印每个调用栈的信息

Source：显示具体函数的资源消耗信息，类似list命令

Disassemble：显示样本总量

SAMPLE:
如果是内存信息SAMOLE这一栏有四个选项

alloc_objects：已分配的对象总量（不管是否已释放）

alloc_space：已分配的内存总量（不管是否已释放）

inuse_objects：已分配但尚未释放的对象数量

inuse_sapce：已分配但尚未释放的内存数量

定位到问题

通过图形和命令行相结合，发现就是github.com/gin-contrib/cache.(*cachedWriter).Write这个地方使用了大量的内存，看到这个包名就恍然大悟了，我们在代码中使用了gin的一个缓存中间件：Cache gin's middleware,对每个接口进行了缓存，包括这个文件下载接口，所以每次请求下载文件就会缓存到内存中。
解决很简单，把这个接口的缓存删除就可以了。

总结

不要在文件下载接口添加缓存，防止OOM；相信自己的代码和分析，少走排查弯路；pprof很强大，以后Go程序性能分析可以用起来。

参考

1. https://pkg.go.dev/runtime/pprof
2. https://github.com/gin-contrib/cache
3. https://www.jishuchi.com/read/gin-practice/3832
4. https://blog.csdn.net/weixin_43710037/article/details/117718665
5. https://blog.csdn.net/zhangkaixuan456/article/details/132775868