使用 pprof 定位 Golang 服务内存占用过高问题的记录

近期有台服务器 “假死”，定为后发现触发条件是其上的 Web 服务的一个压缩包上传解析功能导致的,从代码不好确定是哪个环节导致内存占用过高，决定使用 pprof 排查，以下是定位问题的记录

启用 pprof

引入 pprof，启用 HTTP 服务，监听的端口为 6060（约定俗成，非强制）

package main

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

func main() {
    go func() {
        // pprof 服务器，将暴露在 6060 端口
        if err := http.ListenAndServe(":6060", nil); err != nil {
            panic(err)
        }
    }()
    // ...
}

程序启动后，可以打开网址 http://localhost:6060/debug/pprof/ 查看支持补货的内容，有 CPU、内存等

性能指标

我要排查内存使用情况，所以选择的 heap 性能数据，seconds=30 表示获取一段时间内的指标。在这段时间内，我手动触发了接口，复现高内存占用时刻。

# 获取性能数据
curl -o heap.pprof 'http://localhost:6060/debug/pprof/heap?seconds=30'

将生成的 heap.pprof 获取到本地电脑

可视化分析

Web 可视化功能依赖 graphviz 工具，需要先安装，macOS 通过 brew 安装：

$ brew install graphviz

基于刚刚捕获的性能数据进行分析

$ go tool pprof -http=:8081 heap.pprof

执行命令后会自动打开网页，部分截图如下：

发现端倪

压缩包仅有 32MB，解压后也才 75MB

不应该消耗将近 600+MB 的内存...

继续验证，macOS 系统下，我安装了 gnu-time，相比于自带的 time，gtime 能够显示运行期间最大内存消耗。

静默解压，可以看到使用 unzip 工具，内存消耗是很小的，只有 3664KB

猜测应该是之前引入 AI 提供的 Unzip 函数存在性能问题导致的

验证猜测

以下是代码示例

func Unzip(src string, dest string) error {
    r, err := zip.OpenReader(src)
    if err != nil {
        return err
    }
    defer r.Close()

    for _, f := range r.File {
        fileInArchive, err := f.Open()
        if err != nil {
            return err
        }
        defer fileInArchive.Close()

        path := filepath.Join(dest, f.Name)
        if f.FileInfo().IsDir() {
            os.MkdirAll(path, f.Mode())
        } else {
            f, err := os.OpenFile(path, os.O_WRONLY|os.O_CREATE|os.O_TRUNC, f.Mode())
            if err != nil {
                return err
            }
            _, err = io.Copy(f, fileInArchive)
            if err != nil {
                return err
            }
        }
    }
    return nil
}

调用代码

main.go

func main() {
    err := utility.Unzip("assets.zip", "/tmp/unzip-folder")
    if err != nil {
        fmt.Println(err)
    }
}

编译执行

$ go build -o unzip-test main.go

# 执行
$ gtime ./unzip-test

确实消耗了 728528 KB 的内存，定位到具体函数，问题就好解决了。

代码修复

排查代码发现了问题，以下的代码片段在循环中使用 defer fileInArchive.Close() 关闭文件，而 defer 是在函数执行完成时才会调用，循环时并不会关闭。

for _, f := range r.File {
    fileInArchive, err := f.Open()
    if err != nil {
        return err
    }
    defer fileInArchive.Close()

    // ...
}

接下来优化代码，在循环中直接关闭文件。

func Unzip(src string, dest string) error {
    r, err := zip.OpenReader(src)
    if err != nil {
        return err
    }
    defer r.Close()

    for _, f := range r.File {
        fileInArchive, err := f.Open()
        if err != nil {
            return err
        }

        path := filepath.Join(dest, f.Name)
        if f.FileInfo().IsDir() {
            os.MkdirAll(path, f.Mode())
        } else {
            f, err := os.OpenFile(path, os.O_WRONLY|os.O_CREATE|os.O_TRUNC, f.Mode())
            if err != nil {
                return err
            }
            _, err = io.Copy(f, fileInArchive)
            if err != nil {
                return err
            }
            f.Close()
            fileInArchive.Close()
        }
    }
    return nil
}

重新测试

内存占用降低到了 35.5MB，符合预期，问题修复。

总结

pprof 是 Golang 服务内置的功能，引入并暴露 HTTP 服务即可使用，不应在生产环境暴露
循环内部使用 defer 关闭文件是典型错误，应多留意
AI 提供的代码很容易有 BUG，Review + 单元测试不可或缺