在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 以 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：互斥锁分析，报告互斥锁的竞争情况
在与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)
}
}
直接在浏览器访问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，默认进行30s的CPUProfiling，得到一个分析用的profile文件block（BlockProfiling）：HOST/debug/pprof/block，查看导致阻塞同步的堆栈跟踪
goroutine：$HOST/debug/pprof/goroutine，查看当前所有运行的 goroutines 堆栈跟踪
heap（Memory Profiling）: HOST/debug/pprof/heap，查看活动对象的内存分配情况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结合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程序性能分析可以用起来。
此内容由惯性聚合(RSS阅读器)自动聚合整理，仅供阅读参考。 原文来自 — 版权归原作者所有。