从实例出发，深入理解pprof原理与应用

原创

Michel_Rolle

修改于 2023-12-13 16:24:11

2.2K9

修改于 2023-12-13 16:24:11

文章被收录于专栏：golang分享golang分享

内存泄露

内存泄漏是指在计算机程序中，由于程序未能正确释放已经申请的内存空间，导致系统的可用内存持续减少，最终可能导致程序性能下降甚至崩溃的问题。

Pprof

在pprof图像并不是全能的，因为其不能够涵盖所有的信息，比如一个很长时间在等待状态下的goroutine，其本身是不会消耗CPU的，也就不可能出现在pprof中，但是其可能会导致耗时变慢。

trace中的Goroutine analysis，也可以考虑这个工具，在某些情况下用来分析某一个协程的具体情况。

采用http api来将pprof信息暴露出来以供分析，可以采用net/http/pprof 这个package。下面是一个简单的示例：

这段代码的目的是在后台启动一个HTTP服务器，该服务器用于提供性能剖析数据，以便进行程序性能分析。通过在浏览器中访问相应的URL（通常是http://localhost:8080/debug/pprof/），可以查看应用程序的性能数据。

import _ "net/http/pprof"

go func() {
    http.ListenAndServe("0.0.0.0:8080", nil)
}()

通过 Web API 分析

访问 http://localhost:6060/debug/pprof/ 页面，可以看到总览

输入网址ip:port/debug/pprof/打开pprof主页，大概有这么几类profile信息：

block：提供有关阻塞的 goroutines 的信息，即等待某些资源而被阻塞的 goroutines。
goroutine：显示当前程序中所有 goroutine 的堆栈跟踪信息，用于诊断并发问题。
heap：提供堆内存分配的信息，包括内存占用和对象分布。
mutex：提供有关互斥锁的信息。互斥锁用于同步对共享资源的访问，
threadcreate：提供有关线程创建的信息。在 Go 中，goroutine 是轻量级线程的抽象
allocs：提供有关内存分配的信息。具体来说，它包含了有关分配器操作的数据，可以用于分析应用程序中的内存分配情况。
cmdline：提供了与启动 Go 程序的命令行参数相关的信息。
profile: CPU profile文件。可以在 debug/pprof?seconds=x秒 GET 参数中指定持续时间。获取pprof文件后，使用 go tool pprof x.prof命令分析pprof文件。
threadcreate：线程信息
Trace：当前系统的代码执行的链路情况

通过 dump 文件进行分析

通过执行命令 go tool pprof http://localhost:6060/debug/pprof/profile?seconds=60 会进行 60s 内进行采样（默认 30s），并进入 命令行交互模式：

go tool pprof http://localhost:6060/debug/pprof/profile\?seconds=3

Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile?seconds=3

Saved profile in /Users/youzeliang/pprof/pprof.samples.cpu.002.pb.gz
Type: cpu
Time: Jun 24, 2023 at 6:56pm (CST)
Duration: 3s, Total samples = 0
No samples were found with the default sample value type.
Try "sample_index" command to analyze different sample values.
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)

CPU profile 的 top 命令

在 CPU profile 交互页面输入 topN 可以查看 top N 的概况（N 可省略，默认为 10）

(pprof) top
Showing nodes accounting for 29.92s, 94.56% of 31.64s total
Dropped 117 nodes (cum <= 0.16s)
Showing top 10 nodes out of 33
      flat  flat%   sum%        cum   cum%
    28.52s 90.14% 90.14%     28.58s 90.33%  runtime.cgocall
     0.81s  2.56% 92.70%      0.82s  2.59%  runtime.stdcall1
     0.24s  0.76% 93.46%      0.25s  0.79%  runtime.stdcall3
     0.16s  0.51% 93.96%     29.10s 91.97%  internal/poll.(*FD).writeConsole
     0.05s  0.16% 94.12%     29.28s 92.54%  internal/poll.(*FD).Write
     0.04s  0.13% 94.25%      0.18s  0.57%  runtime.findrunnable
     0.03s 0.095% 94.34%      0.18s  0.57%  runtime.mallocgc
     0.03s 0.095% 94.44%      0.25s  0.79%  runtime.mcall
     0.02s 0.063% 94.50%     29.49s 93.20%  log.(*Logger).Output
     0.02s 0.063% 94.56%     29.71s 93.90%  log.Println
(pprof)

显示的节点在总共 31.64s 的抽样中，占 29.92s，比例 94.56%
在 33 个样本中显示了 top 10
列表解释（cum: cumulative 堆积的）
flat: 在给定函数上运行耗时
flat%: 在给定函数上运行耗时总比例
sum%: 给定函数累计使用 CPU 总比例
cum: 当前函数 以及包含子函数 的调用运行总耗时
cum%: 同上的 CPU 运行耗时总比例
最后一列为函数名称

heap profile 的 top 命令

go tool pprof http://localhost:6060/debug/pprof/heap

$ go tool pprof http://localhost:6060/debug/pprof/heap
Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap
Saved profile in /Users/youzeliang/pprof/pprof.samples.cpu.001.pb.gz
Type: inuse_space
Time: Jun 17, 2020 at 3:52pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)
(pprof) top
Showing nodes accounting for 10.04GB, 100% of 10.04GB total
      flat  flat%   sum%        cum   cum%
   10.04GB   100%   100%    10.04GB   100%  main.Add
         0     0%   100%    10.04GB   100%  main.main.func1
(pprof)

inuse_space: 常驻内存占用情况
alloc_objects：内存临时分配情况

查看堆栈调用信息

go tool pprof http://localhost:6060/debug/pprof/heap

# 如果需要下载对应的图片，只需要在后面添加png即可，例如获取heap的图片

go tool pprof -png http://localhost:6060/debug/pprof/heap > heap.png

以上命令转化为图看的

查看 30 秒内的 CPU 信息

go tool pprof http://localhost:6060/debug/pprof/profile  # 30-second CPU profile
go tool pprof http://localhost:6060/debug/pprof/profile?seconds=120  # 等待120s

# 同理

go tool pprof -png http://localhost:6060/debug/pprof/profile > profile.png  # 转化为图

查看 goroutine 阻塞

go tool pprof http://localhost:6060/debug/pprof/block

收集 5 秒内的执行路径

go tool pprof http://localhost:6060/debug/pprof/trace?seconds=5

争用互斥持有者的堆栈跟踪

go tool pprof http://localhost:6060/debug/pprof/mutex

查看 goroutine profile

go tool pprof http://localhost:6060/debug/pprof/goroutine # goroutine profile

Pprof 分析goroutine泄漏

每1秒创建一个goroutine，每个goroutine分配1M内存，本来内存在goroutine退出以后会自动释放，不存在泄漏的问题，但是由于outCh只有写入没有读取导致channel写入阻塞，整个goroutine也阻塞在37行，进而导致对应分配的内存没有释放，形成内存泄漏

 package main

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

func main() {
	go func() {
		ip := "0.0.0.0:6060"
		if err := http.ListenAndServe(ip, nil); err != nil {
			fmt.Printf(" start %s\n", ip)
			os.Exit(1)
		}
	}()

	outCh := make(chan int)
	stime := time.Now()
	
	for {
		time.Sleep(1 * time.Second)
		go alloc(outCh)
		fmt.Printf("last: %dseconds\n", int(time.Now().Sub(stime).Seconds()))
	}
}

func alloc(outCh chan<- int) {
	buf := make([]byte, 1024*1024*1)
	_ = len(buf)
	fmt.Println("alloc make buffer done")

	outCh <- 0 
	fmt.Println("alloc finished")
}

go tool pprof -png http://localhost:6060/debug/pprof/goroutine > goroutine.png

从图中看出，有101个goroutine累积了

不过上面的demo太简单了，如果去获取内存profile,几乎获取不到啥。以下demo更好的说明

package main

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

func main() {
    go func() {
        ip := "0.0.0.0:6060"
        if err := http.ListenAndServe(ip, nil); err != nil {
            fmt.Printf("start %s", ip)
            os.Exit(1)
        }
    }()

    tick := time.Tick(time.Second / 100)
    var buf []byte
    for range tick {
        buf = append(buf, make([]byte, 1024*1024)...)
    }
}

输入

go tool pprof http://10.171.6.230	:8100/debug/pprof/heap

go tool pprof http://localhost:6060/debug/pprof/heap


Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap
Saved profile in /Users/youzeliang/pprof/pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.003.pb.gz   //<--- 下载到的内存profile文件
Type: inuse_space
Time: Jun 26, 2023 at 11:00pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)
(pprof) help    // 使用help打印所有可用命令
  Commands:
    callgrind        Outputs a graph in callgrind format
    comments         Output all profile comments
    disasm           Output assembly listings annotated with samples
    dot              Outputs a graph in DOT format
    eog              Visualize graph through eog
    evince           Visualize graph through evince
    gif              Outputs a graph image in GIF format
    gv               Visualize graph through gv
    kcachegrind      Visualize report in KCachegrind
    list             Output annotated source for functions matching regexp
    pdf              Outputs a graph in PDF format
    peek             Output callers/callees of functions matching regexp
    png              Outputs a graph image in PNG format
    proto            Outputs the profile in compressed protobuf format
    ps               Outputs a graph in PS format
    raw              Outputs a text representation of the raw profile
    svg              Outputs a graph in SVG format
    tags             Outputs all tags in the profile
    text             Outputs top entries in text form
    top              Outputs top entries in text form
    topproto         Outputs top entries in compressed protobuf format
    traces           Outputs all profile samples in text form
    tree             Outputs a text rendering of call graph
    web              Visualize graph through web browser
    weblist          Display annotated source in a web browser
    o/options        List options and their current values
    q/quit/exit/^D   Exit pprof

  Options:

最常用的：top、list、traces

输入 top

按指标大小列出前10个函数，比如内存是按内存占用多少，CPU是按执行时间多少。

(pprof) top
Showing nodes accounting for 213.25MB, 100% of 213.25MB total
      flat  flat%   sum%        cum   cum%
  213.25MB   100%   100%   213.25MB   100%  main.main
         0     0%   100%   213.25MB   100%  runtime.main

top会列出5个统计数据：

flat: 本函数占用的内存量。
flat%: 本函数内存占使用中内存总量的百分比。
sum%: 前面每一行flat百分比的和，比如第2行虽然的100% 是 100% + 0%。
cum: 是累计量，加入main函数调用了函数f，函数f占用的内存量，也会记进来。
cum%: 是累计量占总量的百分比。

list

查看某个函数的代码，以及该函数每行代码的指标信息，如果函数名不明确，会进行模糊匹配，比如list main会列出main.main和runtime.main。

(pprof) list main.main    // 精确列出函数
Total: 213.25MB
ROUTINE ======================== main.main in /Users/youzeliang/go/src/github.com/youzeliang/goalgorithm/base/pprof/p2/main.go
  213.25MB   213.25MB (flat, cum)   100% of Total
         .          .     13:func main() {
         .          .     14:	// 开启pprof
         .          .     15:	go func() {
         .          .     16:		ip := "0.0.0.0:6060"
         .          .     17:		if err := http.ListenAndServe(ip, nil); err != nil {
         .          .     18:			fmt.Printf("start pprof failed on %s\n", ip)
         .          .     19:			os.Exit(1)
         .          .     20:		}
         .          .     21:	}()
         .          .     22:
         .          .     23:	tick := time.Tick(time.Second / 100)
         .          .     24:	var buf []byte
         .          .     25:	for range tick {
  213.25MB   213.25MB     26:		buf = append(buf, make([]byte, 1024*1024)...)
         .          .     27:	}
         .          .     28:}

可以看到在main.main中的第26行占用了213.25MB内存，左右2个数据分别是flat和cum，含义和top中解释的一样。

traces

打印所有调用栈，以及调用栈的指标信息。

(pprof) traces
Type: inuse_space
Time: Jun 26, 2023 at 11:00pm (CST)
-----------+-------------------------------------------------------
         0   main.main
             runtime.main
-----------+-------------------------------------------------------
     bytes:  213.25MB
  213.25MB   main.main
             runtime.main
-----------+-------------------------------------------------------
     bytes:  170.59MB
         0   main.main
             runtime.main
-----------+-------------------------------------------------------
     bytes:  136.47MB
         0   main.main
             runtime.main
-----------+-------------------------------------------------------
     bytes:  109.17MB
         0   main.main
             runtime.main
-----------+-------------------------------------------------------
     bytes:  87.34MB
         0   main.main
             runtime.main
-----------+-------------------------------------------------------

runtime.main调用了main.main，并且main.main中占用了213.25MB内存。

当然也还可以用

# 也可使用goroutine
go tool pprof http://localhost:6060/debug/pprof/heap

再生成一下，然后用

go tool pprof -base pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.001.pb.gz pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.002.pb.gz

其来对比

如果在本机，也可这样

package main

import (
	"log"
	"net/http"
	_ "net/http/pprof"
	"time"
)

func main() {
	go func() {
		log.Fatal(http.ListenAndServe(":6060", nil))
	}()

	var data [][]byte
	for {
		data = func1(data)
		time.Sleep(1 * time.Second)
	}
}

func func1(data [][]byte) [][]byte {
	data = func2(data)
	return append(data, make([]byte, 1024*1024)) // alloc 1mb
}

func func2(data [][]byte) [][]byte {
	return append(data, make([]byte, 1024*1024)) // alloc 1mb
}

 go tool pprof -http=":6061" localhost:6060/debug/pprof/heap

Go Heap Top

Name 列表示相应的函数名
Flat 列表示该函数自身分配了多少内存
Flat% 列表示 Flat 相对总分配大小的占比
Cum 列表示该函数， 及其调用的所有子函数 一共分配了多少内存
Cum% 列表示 Cum 相对总分配大小的占比

Sum% 列表示自上而下 Flat% 的累加（可以直观的判断出从哪一行往上一共分配的多少内存）上述两种方式可以帮助定位到具体的函数，Go 提供了更细粒度的代码行数级别的分配源统计，在左上角 View 栏下拉点击 Source：

在左上角 View 栏下拉点击 Source：

Go Heap Source

在 CPU Profiling 中我们常用火焰图找宽顶来快速直观地定位热点函数。当然，由于数据模型的同质性，Heap Profiling 数据也可以通过火焰图来展现，在左上角 View 栏下拉点击 Flame Graph：

退出，这种情况就是goroutine泄露。

goroutine执行过程中还存在一些变量，如果这些变量指向堆内存中的内存，GC会认为这些内存仍在使用，不会对其进行回收，这些内存谁都无法使用，造成了内存泄露。

所以goroutine泄露有2种方式造成内存泄露：

goroutine本身的栈所占用的空间造成内存泄露。
goroutine中的变量所占用的堆内存导致堆内存泄露，这一部分是能通过heap profile体现出来的。

怎么确定是goroutine泄露引发的内存泄露

判断依据：总的来说，如果随着时间的推移，未被释放的goroutine的数量一直在慢慢增长的话，这种情况就很有可能是goroutine引发的内存泄露了

package main

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

func main() {
    go func() {
        ip := "0.0.0.0:6060"
        if err := http.ListenAndServe(ip, nil); err != nil {
            fmt.Printf("start ", ip)
            os.Exit(1)
        }
    }()

    outCh := make(chan int)
    // 这里写一个死循环
    go func() {
        if false {
            <-outCh
        }
        select {}
    }()

    // 这里写一个定时器
    tick := time.Tick(time.Second / 100)
    i := 0
    for range tick {
        i++
        fmt.Println(i)
        alloc1(outCh)
    }
}

func alloc1(outCh chan<- int) {
    go alloc2(outCh)
}

func alloc2(outCh chan<- int) {
    func() {
        defer fmt.Println("alloc-fm exit")
       
        buf := make([]byte, 1024*1024*10)
        _ = len(buf)
        fmt.Println("alloc done")

        outCh <- 0 // 53行
    }()
}

编译并运行以上代码，然后使用go tool pprof获取gorourine的profile文件。

go tool pprof http://localhost:6060/debug/pprof/goroutine

然后查看

go tool pprof pprof.goroutine.001.pb.gz

是可以很明显的看出来有很多goroutine被挂起的

所以接下来就要定位goroutine泄漏的地方了

定位goroutine泄露的2种方法

Web可视化查看

方式一

http://ip:port/debug/pprof/goroutine?debug=1

以上图 goroutine profile: total 1788 就是总的协程的数量

紧接着后面就是跟的调用栈、代码行数

根据上面的提示，就能判断1788个goroutine运行到lmain.go的53行：

阻塞的原因是outCh这个写操作无法完成，outCh是无缓冲的通道，并且由于以下代码是死代码，所以goroutine始终没有从outCh读数据，造成outCh阻塞，进而造成无数个alloc2的goroutine阻塞，形成内存泄露：

方式二

url请求中设置debug=2：

http://ip:port/debug/pprof/goroutine?debug=2

第2种方式和第1种方式是互补的，它可以看到每个goroutine的信息：

goroutine 后面的数字是id []中是当前goroutine的状态，阻塞在写channel，并且阻塞了2分钟，长时间运行的系统，能看到阻塞时间更长的情况。
同时，也可以看到调用栈，看当前执行停到哪了：main.go的53行

命令行交互式方法

Web的方法是简单粗暴，无需登录服务器，浏览器打开看看就行了。

命令行交互式只有1种获取goroutine profile的方法，不像Web网页分debug=1和debug=22中方式，并将profile文件保存到本地：

使用list命令的前提是程序的源码在当前机器，不然可没法列出源码。服务器上，通常没有源码，那咋办呢？刚才介绍了Web查看的方式，那里会列出代码行数，我们可以使用wget下载网页：

wget http://localhost:6060/debug/pprof/goroutine?debug=1

下载网页后，利用文本编辑器打开文件，运用关键字"main.alloc2.func1"进行检索，寻找与当前相匹配的调用栈，从而定位到正在阻塞的goroutine所在的行数。别忘了启用debug=2，这样可以详细查看阻塞了多久以及原因。在Web方式中已经详细介绍了这个过程，这里不再展示具体的代码，略过了几十行。

总结

goroutine泄露的本质

goroutine泄露的本质是channel阻塞，无法继续向下执行，导致此goroutine关联的内存都无法释放，进一步造成内存泄露。goroutine泄露的发现和定位
利用好go pprof获取goroutine profile文件，然后利用3个命令top、traces、list定位内存泄露的原因。goroutine泄露的场景

泄露的场景不仅限于以下两类，但因channel相关的泄露是最多的。

channel的读或者写：
1. 无缓冲channel的阻塞通常是写操作因为没有读而阻塞
2. 有缓冲的channel因为缓冲区满了，写操作阻塞
3. 期待从channel读数据，结果没有goroutine写
select操作，select里也是channel操作，如果所有case上的操作阻塞，goroutine也无法继续执行。编码goroutine泄露的建议

为避免goroutine泄露造成内存泄露，启动goroutine前要思考清楚：

goroutine如何退出？
是否会有阻塞造成无法退出？如果有，那么这个路径是否会创建大量的goroutine？

排查思路总结

今后遇到 golang 内存泄漏问题可以按照以下几步进行排查解决：

使用go run时，添加-race标志以检查数据竞争。
确保所有的资源都被正确地关闭，如文件、网络连接等。
可以查看线上的服务器的内存使用情况，确定内存增长是否随着时间的推移而增长；
判断 goroutine 问题；
这里可以使用 1 中提到的监控来观察 goroutine 数量，也可以使用 pprof 进行采样判断，判断 goroutine 数量是否出现了异常增长。
判断代码问题；
利用 pprof，通过函数名称定位具体代码行数，可以通过 pprof 的 graph、source 等手段去定位；
排查整个调用链是否出现了上述场景中的问题，如 select 阻塞、channel 阻塞、slice 使用不当等问题，优先考虑自身代码逻辑问题，其次考虑框架是否存在不合理地方；
解决对应问题并在测试环境中观察，通过后上线进行观察；
pprof: 是 Go 语言中分析程序运行性能的工具，它能提供各种性能数据包括 cpu、heap、goroutine 等等，可以通过报告生成、Web 可视化界面、交互式终端三种方式来使用 pprof

大量的访问也可能造成内存泄露，这时候也要考虑用好熔断组件，比如阿里开源的sentinel circuitbreaker

原创声明：本文系作者授权腾讯云开发者社区发表，未经许可，不得转载。

如有侵权，请联系 cloudcommunity@tencent.com 删除。

2023腾讯·技术创作特训营第四期

内存

内存泄漏

原创声明：本文系作者授权腾讯云开发者社区发表，未经许可，不得转载。

如有侵权，请联系 cloudcommunity@tencent.com 删除。

2023腾讯·技术创作特训营第四期

内存

内存泄漏

登录后参与评论

0 条评论

热度