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

Published: 2024-04-19

Tags: 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,符合预期,问题修复。

总结

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