最近解决了我们项目中的一个内存泄露问题,事实再次证明pprof是一个好工具,但掌握好工具的正确用法,才能发挥好工具的威力,不然就算你手里有屠龙刀,也成不了天下第一,本文就是带你用pprof定位内存泄露问题。
关于Go的内存泄露有这么一句话不知道你听过没有:

10次内存泄露,有9次是goroutine泄露。

我所解决的问题,也是goroutine泄露导致的内存泄露,所以这篇文章主要介绍Go程序的goroutine泄露,掌握了如何定位和解决goroutine泄露,就掌握了内存泄露的大部分场景

本文草稿最初数据都是生产坏境数据,为了防止敏感内容泄露,全部替换成了demo数据,demo的数据比生产环境数据简单多了,更适合入门理解,有助于掌握pprof。

go pprof基本知识

定位goroutine泄露会使用到pprof,pprof是Go的性能工具,在开始介绍内存泄露前,先简单介绍下pprof的基本使用,更详细的使用给大家推荐了资料

什么是pprof

pprof是Go的性能分析工具,在程序运行过程中,可以记录程序的运行信息,可以是CPU使用情况、内存使用情况、goroutine运行情况等,当需要性能调优或者定位Bug时候,这些记录的信息是相当重要。

基本使用

使用pprof有多种方式,Go已经现成封装好了1个:net/http/pprof,使用简单的几行命令,就可以开启pprof,记录运行信息,并且提供了Web服务,能够通过浏览器和命令行2种方式获取运行数据。
看个最简单的pprof的例子:
文件:golang_step_by_step/pprof/pprof/demo.go

  1. package main
  2. import (
  3. "fmt"
  4. "net/http"
  5. _ "net/http/pprof"
  6. )
  7. func main() {
  8. // 开启pprof,监听请求
  9. ip := "0.0.0.0:6060"
  10. if err := http.ListenAndServe(ip, nil); err != nil {
  11. fmt.Printf("start pprof failed on %s\n", ip)
  12. }
  13. }

浏览器方式

输入网址ip:port/debug/pprof/打开pprof主页
image.png

命令行方式

当连接在服务器终端上的时候,是没有浏览器可以使用的,Go提供了命令行的方式,能够获取以上5类信息,这种方式用起来更方便。
使用命令go tool pprof url可以获取指定的profile文件,此命令会发起http请求,然后下载数据到本地,之后进入交互式模式,就像gdb一样,可以使用命令查看运行信息,以下是5类请求的方式:

  1. # 下载cpu profile,默认从当前开始收集30s的cpu使用情况,需要等待30s
  2. go tool pprof http://localhost:6060/debug/pprof/profile # 30-second CPU profile
  3. go tool pprof http://localhost:6060/debug/pprof/profile?seconds=120 # wait 120s
  4. # 下载heap profile
  5. go tool pprof http://localhost:6060/debug/pprof/heap # heap profile
  6. # 下载goroutine profile
  7. go tool pprof http://localhost:6060/debug/pprof/goroutine # goroutine profile
  8. # 下载block profile
  9. go tool pprof http://localhost:6060/debug/pprof/block # goroutine blocking profile
  10. # 下载mutex profile
  11. go tool pprof http://localhost:6060/debug/pprof/mutex

上面的pprof/demo.go太简单了,如果去获取内存profile,几乎获取不到什么,换一个Demo进行内存profile的展示:

  1. // 展示内存增长和pprof,并不是泄露
  2. package main
  3. import (
  4. "fmt"
  5. "net/http"
  6. _ "net/http/pprof"
  7. "os"
  8. "time"
  9. )
  10. // 运行一段时间:fatal error: runtime: out of memory
  11. func main() {
  12. // 开启pprof
  13. go func() {
  14. ip := "0.0.0.0:6060"
  15. if err := http.ListenAndServe(ip, nil); err != nil {
  16. fmt.Printf("start pprof failed on %s\n", ip)
  17. os.Exit(1)
  18. }
  19. }()
  20. tick := time.Tick(time.Second / 100)
  21. var buf []byte
  22. for range tick {
  23. buf = append(buf, make([]byte, 1024*1024)...)
  24. }
  25. }

上面这个demo会不断的申请内存,把它编译运行起来,然后执行:

  1. $ go tool pprof http://localhost:6060/debug/pprof/heap
  2. Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap
  3. Saved profile in /home/ubuntu/pprof/pprof.demo.alloc_objects.alloc_space.inuse_objects.inuse_space.001.pb.gz //<--- 下载到的内存profile文件
  4. File: demo // 程序名称
  5. Build ID: a9069a125ee9c0df3713b2149ca859e8d4d11d5a
  6. Type: inuse_space
  7. Time: May 16, 2019 at 8:55pm (CST)
  8. Entering interactive mode (type "help" for commands, "o" for options)
  9. (pprof)
  10. (pprof)
  11. (pprof) help // 使用help打印所有可用命令
  12. Commands:
  13. callgrind Outputs a graph in callgrind format
  14. comments Output all profile comments
  15. disasm Output assembly listings annotated with samples
  16. dot Outputs a graph in DOT format
  17. eog Visualize graph through eog
  18. evince Visualize graph through evince
  19. gif Outputs a graph image in GIF format
  20. gv Visualize graph through gv
  21. kcachegrind Visualize report in KCachegrind
  22. list Output annotated source for functions matching regexp
  23. pdf Outputs a graph in PDF format
  24. peek Output callers/callees of functions matching regexp
  25. png Outputs a graph image in PNG format
  26. proto Outputs the profile in compressed protobuf format
  27. ps Outputs a graph in PS format
  28. raw Outputs a text representation of the raw profile
  29. svg Outputs a graph in SVG format
  30. tags Outputs all tags in the profile
  31. text Outputs top entries in text form
  32. top Outputs top entries in text form
  33. topproto Outputs top entries in compressed protobuf format
  34. traces Outputs all profile samples in text form
  35. tree Outputs a text rendering of call graph
  36. web Visualize graph through web browser
  37. weblist Display annotated source in a web browser
  38. o/options List options and their current values
  39. quit/exit/^D Exit pprof
  40. ....

以上信息我们只关注2个地方:

  1. 下载得到的文件:/home/ubuntu/pprof/pprof.demo.alloc_objects.alloc_space.inuse_objects.inuse_space.001.pb.gz,这其中包含了程序名demo,profile类型alloc已分配的内存,inuse代表使用中的内存。
  2. help可以获取帮助,最先会列出支持的命令,想掌握pprof,要多看看,多尝试。

关于命令,本文只会用到3个,我认为也是最常用的:toplisttraces,分别介绍一下。

top

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

  1. (pprof) top
  2. Showing nodes accounting for 814.62MB, 100% of 814.62MB total
  3. flat flat% sum% cum cum%
  4. 814.62MB 100% 100% 814.62MB 100% main.main
  5. 0 0% 100% 814.62MB 100% runtime.main

top会列出5个统计数据:

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

list

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

  1. (pprof) list main.main // 精确列出函数
  2. Total: 814.62MB
  3. ROUTINE ======================== main.main in /home/ubuntu/heap/demo2.go
  4. 814.62MB 814.62MB (flat, cum) 100% of Total
  5. . . 20: }()
  6. . . 21:
  7. . . 22: tick := time.Tick(time.Second / 100)
  8. . . 23: var buf []byte
  9. . . 24: for range tick {
  10. 814.62MB 814.62MB 25: buf = append(buf, make([]byte, 1024*1024)...)
  11. . . 26: }
  12. . . 27:}
  13. . . 28:
  14. (pprof) list main // 匹配所有函数名带main的函数
  15. Total: 814.62MB
  16. ROUTINE ======================== main.main in /home/ubuntu/heap/demo2.go
  17. 814.62MB 814.62MB (flat, cum) 100% of Total
  18. . . 20: }()
  19. . . 21:
  20. ..... // 省略几行
  21. . . 28:
  22. ROUTINE ======================== runtime.main in /usr/lib/go-1.10/src/runtime/proc.go
  23. 0 814.62MB (flat, cum) 100% of Total
  24. . . 193: // A program compiled with -buildmode=c-archive or c-shared
  25. ..... // 省略几行

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

traces

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

  1. (pprof) traces
  2. File: demo2
  3. Type: inuse_space
  4. Time: May 16, 2019 at 7:08pm (CST)
  5. -----------+-------------------------------------------------------
  6. bytes: 813.46MB
  7. 813.46MB main.main
  8. runtime.main
  9. -----------+-------------------------------------------------------
  10. bytes: 650.77MB
  11. 0 main.main
  12. runtime.main
  13. ....... // 省略几十行

每个- - - - - 隔开的是一个调用栈,能看到runtime.main调用了main.main,并且main.main中占用了813.46MB内存。
其他的profile操作和内存是类似的,这里就不展示了。
这里只是简单介绍本文用到的pprof的功能,pprof功能很强大,也经常和benchmark结合起来

什么是内存泄露

内存泄露指的是程序运行过程中已不再使用的内存,没有被释放掉,导致这些内存无法被使用,直到程序结束这些内存才被释放的问题。
Go虽然有GC来回收不再使用的堆内存,减轻了开发人员对内存的管理负担,但这并不意味着Go程序不再有内存泄露问题。在Go程序中,如果没有Go语言的编程思维,也不遵守良好的编程实践,就可能埋下隐患,造成内存泄露问题。

怎么发现内存泄露

在Go中发现内存泄露有2种方法,一个是通用的监控工具,另一个是go pprof:

  1. 监控工具:固定周期对进程的内存占用情况进行采样,数据可视化后,根据内存占用走势(持续上升),很容易发现是否发生内存泄露。
  2. go pprof:适合没有监控工具的情况,使用Go提供的pprof工具判断是否发生内存泄露。

这2种方式分别介绍一下。

监控工具查看进程内在占用情况

如果使用云平台部署Go程序,云平台都提供了内存查看的工具,可以查看OS的内存占用情况和某个进程的内存占用情况,比如阿里云,我们在1个云主机上只部署了1个Go服务,所以OS的内存占用情况,基本是也反映了进程内存占用情况,OS内存占用情况如下,可以看到随着时间的推进,内存的占用率在不断的提高,这是内存泄露的最明显现象
image.png

go pprof发现存在内存问题

如果你Google或者百度,Go程序内存泄露的文章,它总会告诉你使用pprof heap,能够生成漂亮的调用路径图,火焰图等等,然后你根据调用路径就能定位内存泄露问题,我最初也是对此深信不疑,尝试了若干天后,只是发现内存泄露跟某种场景有关,根本找不到内存泄露的根源,如果哪位朋友用heap就能定位内存泄露的线上问题,麻烦介绍下
后来读了Dave的《High Performance Go Workshop》,刷新了对heap的认识,内存pprof的简要内容如下:
image.png
Dave讲了以下几点:

  1. 内存profiling记录的是堆内存分配的情况,以及调用栈信息,并不是进程完整的内存情况,猜测这也是在go pprof中称为heap而不是memory的原因。
  2. 栈内存的分配是在调用栈结束后会被释放的内存,所以并不在内存profile中
  3. 内存profiling是基于抽样的,默认是每1000次堆内存分配,执行1次profile记录。
  4. 因为内存profiling是基于抽样和它跟踪的是已分配的内存,而不是使用中的内存,(比如有些内存已经分配,看似使用,但实际以及不使用的内存,比如内存泄露的那部分),所以不能使用内存profiling衡量程序总体的内存使用情况
  5. Dave个人观点:使用内存profiling不能够发现内存泄露

基于目前对heap的认知,我有2个观点:

  1. heap能帮助我们发现内存问题,但不一定能发现内存泄露问题,这个看法与Dave是类似的。heap记录了内存分配的情况,我们能通过heap观察内存的变化,增长与减少,内存主要被哪些代码占用了,程序存在内存问题,这只能说明内存有使用不合理的地方,但并不能说明这是内存泄露。
  2. heap在帮助定位内存泄露原因上贡献的力量微乎其微。如第一条所言,能通过heap找到占用内存多的位置,但这个位置通常不一定是内存泄露,就算是内存泄露,也只是内存泄露的结果,并不是真正导致内存泄露的根源。

接下来,我介绍怎么用heap发现问题,然后再解释为什么heap几乎不能定位内存泄露的根因。

怎么用heap发现内存问题

使用pprof的heap能够获取程序运行时的内存信息,在程序平稳运行的情况下,每个一段时间使用heap获取内存的profile,然后使用**base**能够对比两个profile文件的差别,就像**diff**命令一样显示出增加和减少的变化,使用一个简单的demo来说明heap和base的使用,依然使用demo2进行展示。

  1. // 展示内存增长和pprof,并不是泄露
  2. package main
  3. import (
  4. "fmt"
  5. "net/http"
  6. _ "net/http/pprof"
  7. "os"
  8. "time"
  9. )
  10. // 运行一段时间:fatal error: runtime: out of memory
  11. func main() {
  12. // 开启pprof
  13. go func() {
  14. ip := "0.0.0.0:6060"
  15. if err := http.ListenAndServe(ip, nil); err != nil {
  16. fmt.Printf("start pprof failed on %s\n", ip)
  17. os.Exit(1)
  18. }
  19. }()
  20. tick := time.Tick(time.Second / 100)
  21. var buf []byte
  22. for range tick {
  23. buf = append(buf, make([]byte, 1024*1024)...)
  24. }
  25. }

将上面代码运行起来,执行以下命令获取profile文件,Ctrl-D退出,1分钟后再获取1次。

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

我已经获取到了两个profile文件:

  1. $ ls
  2. pprof.demo2.alloc_objects.alloc_space.inuse_objects.inuse_space.001.pb.gz
  3. pprof.demo2.alloc_objects.alloc_space.inuse_objects.inuse_space.002.pb.gz

使用base把001文件作为基准,然后用002和001对比,先执行toptop的对比,然后执行list main列出main函数的内存对比,结果如下:

  1. $ go tool pprof -base pprof.demo2.alloc_objects.alloc_space.inuse_objects.inuse_space.001.pb.gz pprof.demo2.alloc_objects.alloc_space.inuse_objects.inuse_space.002.pb.gz
  2. File: demo2
  3. Type: inuse_space
  4. Time: May 14, 2019 at 2:33pm (CST)
  5. Entering interactive mode (type "help" for commands, "o" for options)
  6. (pprof)
  7. (pprof)
  8. (pprof) top
  9. Showing nodes accounting for 970.34MB, 32.30% of 3003.99MB total
  10. flat flat% sum% cum cum%
  11. 970.34MB 32.30% 32.30% 970.34MB 32.30% main.main // 看这
  12. 0 0% 32.30% 970.34MB 32.30% runtime.main
  13. (pprof)
  14. (pprof)
  15. (pprof) list main.main
  16. Total: 2.93GB
  17. ROUTINE ======================== main.main in /home/ubuntu/heap/demo2.go
  18. 970.34MB 970.34MB (flat, cum) 32.30% of Total
  19. . . 20: }()
  20. . . 21:
  21. . . 22: tick := time.Tick(time.Second / 100)
  22. . . 23: var buf []byte
  23. . . 24: for range tick {
  24. 970.34MB 970.34MB 25: buf = append(buf, make([]byte, 1024*1024)...) // 看这
  25. . . 26: }
  26. . . 27:}
  27. . . 28:

top列出了main.mainruntime.mainmain.main就是我们编写的main函数,runtime.main是runtime包中的main函数,也就是所有main函数的入口
top显示main.main 第2次内存占用,比第1次内存占用多了970.34MB。
list main.main告诉了我们增长的内存都在这一行:

  1. buf = append(buf, make([]byte, 1024*1024)...)

heap“不能”定位内存泄露

heap能显示内存的分配情况,以及哪行代码占用了多少内存,我们能轻易的找到占用内存最多的地方,如果这个地方的数值还在不断怎大,基本可以认定这里就是内存泄露的位置。

曾想按图索骥,从内存泄露的位置,根据调用栈向上查找,总能找到内存泄露的原因,这种方案看起来是不错的,但实施起来却找不到内存泄露的原因,结果是事半功倍。

原因在于一个Go程序,其中有大量的goroutine,这其中的调用关系也许有点复杂,也许内存泄露是在某个三方包里。举个栗子,比如下面这幅图,每个椭圆代表1个goroutine,其中的数字为编号,箭头代表调用关系。heap profile显示g111(最下方标红节点)这个协程的代码出现了泄露,任何一个从g101到g111的调用路径都可能造成了g111的内存泄露,有2类可能:

  1. 该goroutine只调用了少数几次,但消耗了大量的内存,说明每个goroutine调用都消耗了不少内存,内存泄露的原因基本就在该协程内部
  2. 该goroutine的调用次数非常多,虽然每个协程调用过程中消耗的内存不多,但该调用路径上,协程数量巨大,造成消耗大量的内存,并且这些goroutine由于某种原因无法退出,占用的内存不会释放,内存泄露的原因在到g111调用路径上某段代码实现有问题,造成创建了大量的g111

第2种情况,就是goroutine泄露,这是通过heap无法发现的,所以heap在定位内存泄露这件事上,发挥的作用不大
image.png

goroutine泄露怎么导致内存泄露

每个goroutine占用2KB内存,泄露1百万goroutine至少泄露2KB * 1000000 = 2GB内存,为什么说至少呢?

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

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

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

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

判断依据:在节点正常运行的情况下,隔一段时间获取goroutine的数量,如果后面获取的那次,某些goroutine比前一次多,如果多获取几次,是持续增长的,就极有可能是goroutine泄露
goroutine导致内存泄露的demo:

  1. // goroutine泄露导致内存泄露
  2. package main
  3. import (
  4. "fmt"
  5. "net/http"
  6. _ "net/http/pprof"
  7. "os"
  8. "time"
  9. )
  10. func main() {
  11. // 开启pprof
  12. go func() {
  13. ip := "0.0.0.0:6060"
  14. if err := http.ListenAndServe(ip, nil); err != nil {
  15. fmt.Printf("start pprof failed on %s\n", ip)
  16. os.Exit(1)
  17. }
  18. }()
  19. outCh := make(chan int)
  20. // 死代码,永不读取
  21. go func() {
  22. if false {
  23. <-outCh
  24. }
  25. select {}
  26. }()
  27. // 每s起100个goroutine,goroutine会阻塞,不释放内存
  28. tick := time.Tick(time.Second / 100)
  29. i := 0
  30. for range tick {
  31. i++
  32. fmt.Println(i)
  33. alloc1(outCh)
  34. }
  35. }
  36. func alloc1(outCh chan<- int) {
  37. go alloc2(outCh)
  38. }
  39. func alloc2(outCh chan<- int) {
  40. func() {
  41. defer fmt.Println("alloc-fm exit")
  42. // 分配内存,假用一下
  43. buf := make([]byte, 1024*1024*10)
  44. _ = len(buf)
  45. fmt.Println("alloc done")
  46. outCh <- 0 // 53行
  47. }()
  48. }

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

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

已经通过pprof命令获取了2个goroutine的profile文件:

  1. $ ls
  2. /home/ubuntu/pprof/pprof.leak_demo.goroutine.001.pb.gz
  3. /home/ubuntu/pprof/pprof.leak_demo.goroutine.002.pb.gz

同heap一样,我们可以使用base对比2个goroutine profile文件

  1. $go tool pprof -base pprof.leak_demo.goroutine.001.pb.gz pprof.leak_demo.goroutine.002.pb.gz
  2. File: leak_demo
  3. Type: goroutine
  4. Time: May 16, 2019 at 2:44pm (CST)
  5. Entering interactive mode (type "help" for commands, "o" for options)
  6. (pprof)
  7. (pprof) top
  8. Showing nodes accounting for 20312, 100% of 20312 total
  9. flat flat% sum% cum cum%
  10. 20312 100% 100% 20312 100% runtime.gopark
  11. 0 0% 100% 20312 100% main.alloc2
  12. 0 0% 100% 20312 100% main.alloc2.func1
  13. 0 0% 100% 20312 100% runtime.chansend
  14. 0 0% 100% 20312 100% runtime.chansend1
  15. 0 0% 100% 20312 100% runtime.goparkunlock
  16. (pprof)

可以看到运行到runtime.gopark的goroutine数量增加了20312个。再通过002文件,看一眼执行到gopark的goroutine数量,即挂起的goroutine数量:

  1. go tool pprof pprof.leak_demo.goroutine.002.pb.gz
  2. File: leak_demo
  3. Type: goroutine
  4. Time: May 16, 2019 at 2:47pm (CST)
  5. Entering interactive mode (type "help" for commands, "o" for options)
  6. (pprof) top
  7. Showing nodes accounting for 24330, 100% of 24331 total
  8. Dropped 32 nodes (cum <= 121)
  9. flat flat% sum% cum cum%
  10. 24330 100% 100% 24330 100% runtime.gopark
  11. 0 0% 100% 24326 100% main.alloc2
  12. 0 0% 100% 24326 100% main.alloc2.func1
  13. 0 0% 100% 24326 100% runtime.chansend
  14. 0 0% 100% 24326 100% runtime.chansend1
  15. 0 0% 100% 24327 100% runtime.goparkunlock

显示有24330个goroutine被挂起,这不是goroutine泄露这是啥?已经能确定八九成goroutine泄露了。
是什么导致如此多的goroutine被挂起而无法退出?接下来就看怎么定位goroutine泄露。

定位goroutine泄露的2种方法

使用pprof有2种方式,一种是web网页,一种是go tool pprof命令行交互,这两种方法查看goroutine都支持,但有轻微不同,也有各自的优缺点。
我们先看Web的方式,再看命令行交互的方式,这两种都很好使用,结合起来用也不错。

Web可视化查看

Web方式适合web服务器的端口能访问的情况,使用起来方便,有2种方式:

  1. 查看某条调用路径上,当前阻塞在此goroutine的数量
  2. 查看所有goroutine的运行栈(调用路径),可以显示阻塞在此的时间

    方式一

    url请求中设置debug=1:

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

    image.png
    看起来密密麻麻的,其实简单又十分有用,看上图标出来的部分,手机上图看起来可能不方便,那就放大图片,或直接看下面各字段的含义:

  3. goroutine profile: total 32023:32023是存活的goroutine的总数量

  4. 32015 @ 0x42e15a 0x42e20e 0x40534b 0x4050e5 ...:32015代表当前有32015个goroutine运行这个调用栈,并且停在相同位置,@后面的十六进制,现在用不到这个数据,所以暂不深究了。
  5. 下面是当前goroutine的调用栈,列出了函数和所在文件的行数,这个行数对定位很有帮助,如下:

    1. 32015 @ 0x42e15a 0x42e20e 0x40534b 0x4050e5 0x6d8559 0x6d831b 0x45abe1
    2. # 0x6d8558 main.alloc2.func1+0xf8 /home/ubuntu/heap/leak_demo.go:53
    3. # 0x6d831a main.alloc2+0x2a /home/ubuntu/heap/leak_demo.go:54

    根据上面的提示,就能判断32015个goroutine运行到leak_demo.go的53行:

    1. func alloc2(outCh chan<- int) {
    2. func() {
    3. defer fmt.Println("alloc-fm exit")
    4. // 分配内存,假用一下
    5. buf := make([]byte, 1024*1024*10)
    6. _ = len(buf)
    7. fmt.Println("alloc done")
    8. outCh <- 0 // 53行
    9. }()
    10. }

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

    1. if false {
    2. <-outCh
    3. }

    方式二

    url请求中设置debug=2:

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

    image.png
    第2种方式和第1种方式是互补的,它可以看到每个goroutine的信息:

  6. goroutine 20 [chan send, 2 minutes]:20是goroutine id,[]中是当前goroutine的状态,阻塞在写channel,并且阻塞了2分钟,长时间运行的系统,你能看到阻塞时间更长的情况。

  7. 同时,也可以看到调用栈,看当前执行停到哪了:leak_demo.go的53行,
    1. goroutine 20 [chan send, 2 minutes]:
    2. main.alloc2.func1(0xc42015e060)
    3. /home/ubuntu/heap/leak_demo.go:53 +0xf9 // 这
    4. main.alloc2(0xc42015e060)
    5. /home/ubuntu/heap/leak_demo.go:54 +0x2b
    6. created by main.alloc1
    7. /home/ubuntu/heap/leak_demo.go:42 +0x3f

命令行交互式方法

Web的方法是简单粗暴,无需登录服务器,浏览器打开看看就行了。但就像前面提的,没有浏览器可访问时,命令行交互式才是最佳的方式,并且也是手到擒来,感觉比Web一样方便。
命令行交互式只有1种获取goroutine profile的方法,不像Web网页分debug=1debug=22中方式,并将profile文件保存到本地:

  1. // 注意命令没有`debug=1`,debug=1,加debug有些版本的go不支持
  2. $ go tool pprof http://0.0.0.0:6060/debug/pprof/goroutine
  3. Fetching profile over HTTP from http://localhost:6061/debug/pprof/goroutine
  4. Saved profile in /home/ubuntu/pprof/pprof.leak_demo.goroutine.001.pb.gz // profile文件保存位置
  5. File: leak_demo
  6. Type: goroutine
  7. Time: May 16, 2019 at 2:44pm (CST)
  8. Entering interactive mode (type "help" for commands, "o" for options)
  9. (pprof)

命令行只需要掌握3个命令就好了:

  1. top:显示正运行到某个函数goroutine的数量
  2. traces:显示所有goroutine的调用栈
  3. list:列出代码详细的信息。

我们依然使用leak_demo.go这个demo,

  1. $ go tool pprof -base pprof.leak_demo.goroutine.001.pb.gz pprof.leak_demo.goroutine.002.pb.gz
  2. File: leak_demo
  3. Type: goroutine
  4. Time: May 16, 2019 at 2:44pm (CST)
  5. Entering interactive mode (type "help" for commands, "o" for options)
  6. (pprof)
  7. (pprof)
  8. (pprof) top
  9. Showing nodes accounting for 20312, 100% of 20312 total
  10. flat flat% sum% cum cum%
  11. 20312 100% 100% 20312 100% runtime.gopark
  12. 0 0% 100% 20312 100% main.alloc2
  13. 0 0% 100% 20312 100% main.alloc2.func1
  14. 0 0% 100% 20312 100% runtime.chansend
  15. 0 0% 100% 20312 100% runtime.chansend1
  16. 0 0% 100% 20312 100% runtime.goparkunlock
  17. (pprof)
  18. (pprof) traces
  19. File: leak_demo
  20. Type: goroutine
  21. Time: May 16, 2019 at 2:44pm (CST)
  22. -----------+-------------------------------------------------------
  23. 20312 runtime.gopark
  24. runtime.goparkunlock
  25. runtime.chansend
  26. runtime.chansend1 // channel发送
  27. main.alloc2.func1 // alloc2中的匿名函数
  28. main.alloc2
  29. -----------+-------------------------------------------------------

top命令在怎么确定是goroutine泄露引发的内存泄露介绍过了,直接看traces命令,traces能列出002中比001中多的那些goroutine的调用栈,这里只有1个调用栈,有20312个goroutine都执行这个调用路径,可以看到alloc2中的匿名函数alloc2.func1调用了写channel的操作,然后阻塞挂起了goroutine,使用list列出alloc2.func1的代码,显示有20312个goroutine阻塞在53行:

  1. (pprof) list main.alloc2.func1
  2. Total: 20312
  3. ROUTINE ======================== main.alloc2.func1 in /home/ubuntu/heap/leak_demo.go
  4. 0 20312 (flat, cum) 100% of Total
  5. . . 48: // 分配内存,假用一下
  6. . . 49: buf := make([]byte, 1024*1024*10)
  7. . . 50: _ = len(buf)
  8. . . 51: fmt.Println("alloc done")
  9. . . 52:
  10. . 20312 53: outCh <- 0 // 看这
  11. . . 54: }()
  12. . . 55:}
  13. . . 56:

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

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

下载网页后,使用编辑器打开文件,使用关键字main.alloc2.func1进行搜索,找到与当前相同的调用栈,就可以看到该goroutine阻塞在哪一行了,不要忘记使用debug=2还可以看到阻塞了多久和原因,Web方式中已经介绍了,此处省略代码几十行。

heap学习记录

之前找了许多关于heap消息的记录,但始终没找到相关信息,没办法自己看代码吧
demo如下:

  1. package main
  2. import (
  3. "fmt"
  4. "net/http"
  5. _ "net/http/pprof"
  6. "os"
  7. "runtime"
  8. "time"
  9. )
  10. // 运行一段时间:fatal error: runtime: out of memory
  11. func main() {
  12. // 开启pprof
  13. go func() {
  14. ip := "0.0.0.0:6060"
  15. if err := http.ListenAndServe(ip, nil); err != nil {
  16. fmt.Printf("start pprof failed on %s\n", ip)
  17. os.Exit(1)
  18. }
  19. }()
  20. runtime.MemProfileRate = 1
  21. tick := time.Tick(time.Second / 100)
  22. var buf []byte
  23. index := 0
  24. for range tick {
  25. buf = append(buf, make([]byte, 1024)...)
  26. index++
  27. fmt.Println(index)
  28. }
  29. fmt.Println(len(buf))
  30. }

image.png
先说说 heap前的478 含义

  1. var heapProfile = &Profile{
  2. name: "heap",
  3. count: countHeap, // 上面的478 就是countHeap这个方法得来的
  4. write: writeHeap, // 这个是详情页生成方法
  5. }
  6. // countHeap returns the number of records in the heap profile.
  7. func countHeap() int {
  8. n, _ := runtime.MemProfile(nil, true)
  9. return n
  10. }

根据上面得知,478就是程序记录的内存分配的采样总次数,那什么触发采样?

  1. var MemProfileRate int = 512 * 1024

在runtime包中,有这个变量MemProfileRate,单位为byte,默认配置即没分配512kb做一次采样,设置为0不采样,逻辑入口可在runtime/malloc.go中的mallocgc函数找到

接着看链接里详细内容

一、总览信息 MemProfileRecord

  1. heap profile: 154: 3767760 [21008: 19188936] @ heap/2
  2. 相关字段的内容来源 runtime/pprof/pprof.go:597中可以找到,这里只说明是什么
  3. 154: 正在使用的对象
  4. 3767760: 正在使用的内存
  5. 21008: 分配的对象
  6. 19188936: 分配的内存
  7. @ heap/2 中的2 = 2*runtime.MemProfileRate

二、具体分配堆栈信息 []MemProfileRecord

  1. 1: 3719168 [1: 3719168] @ 0x128e87c 0x103b4b6 0x1071641
  2. # 0x128e87b main.main+0x1db /Users/mac/Desktop/go/commons/gintest/ginpproftest.go:28
  3. # 0x103b4b5 runtime.main+0x255 /usr/local/go/src/runtime/proc.go:225
  4. 1: 3719168 [1: 3719168] :其含义与总览信息里的相同

三、内存申请和分配的统计信息 MemStats
内存申请和分配的统计信息总览信息是对不上的,如果需要的定位哪里内存使用过多,可能存在泄漏,应该看具体分配堆栈信息

这里描述的整个程序内存使用即分配情况
image.png

参考:https://segmentfault.com/a/1190000019222661