本人小白,刚开始接触go就遇到了一个内存问题,在进行内存分析的时候发现了一下比较好的工具,在此留下记录。

废话不多说,直接开整。

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

基本使用方法

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

废话不多说先上例子:

package main

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

func main() {
    // 开启pprof,监听请求
    ip := "0.0.0.0:6060"
    if err := http.ListenAndServe(ip, nil); err != nil {
        fmt.Printf("start pprof failed on %s\n", ip)
        os.Exit(1)
    }
    // end pprof

    // do something 下面是你的工程代码
    ........
}

如图所示,将代码添加到main方法中。然后就是打镜像——喝茶——等镜像制作——等镜像制作——等镜像制作……发布

下面我门来说一下主要的操作命令命令:

(一)获取堆栈信息

$ go tool pprof -inuse_space http://ip:amdin_port/debug/pprof/heap

-inuse_space参数就是当前服务使用的内存情况,还有一个-alloc_space参数是指服务启动以来总共分配的内存情况,前者更直观一些。

root@sns-ads-service06:~/pprof# go tool pprof -inuse_space http://localhost:6060/debug/pprof/heap
Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap
Saved profile in /root/pprof/pprof.123.alloc_objects.alloc_space.inuse_objects.inuse_space.003.pb.gz
File: thriftcapture
Build ID: 1da7c49a46e05f63089a7eecbe14129ad3948566
Type: inuse_space
Time: Apr 14, 2022 at 1:51am (UTC)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)

1,这个命令执行完成后会生成内存信息的图例,如上图中第三行所示可打开内存图进行查看

Saved profile in /root/pprof/pprof.123.alloc_objects.alloc_space.inuse_objects.inuse_space.003.pb.gz

这其中包含了程序名123,profile类型alloc已分配的内存,inuse代表使用中的内存。

关于命令,我只用到了2个,top和list,其他命令大家可以自行探索,不再赘述。(可以通过help命令查看所有命令)

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

root@sns-ads-service06:~/pprof# go tool pprof -inuse_space http://localhost:6060/debug/pprof/heap
Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap
Saved profile in /root/pprof/pprof.thriftcapture.alloc_objects.alloc_space.inuse_objects.inuse_space.003.pb.gz
File: thriftcapture
Build ID: 1da7c49a46e05f63089a7eecbe14129ad3948566
Type: inuse_space
Time: Apr 14, 2022 at 1:51am (UTC)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 9034.64kB, 100% of 9034.64kB total
Showing top 10 nodes out of 23
      flat  flat%   sum%        cum   cum%
 5120.23kB 56.67% 56.67%  5120.23kB 56.67%  main.CopyMulty
 2368.33kB 26.21% 82.89%  2368.33kB 26.21%  github.com/buger/goreplay/raw_socket_listener.NewListener
 1034.03kB 11.45% 94.33%  1034.03kB 11.45%  runtime.procresize
  512.05kB  5.67%   100%   512.05kB  5.67%  os.newFile
         0     0%   100%   512.05kB  5.67%  github.com/buger/goreplay/raw_socket_listener.(*Listener).readPcap.func1
         0     0%   100%   512.05kB  5.67%  github.com/buger/goreplay/rlog.(*RLogger).GetMemoryUsageRate
         0     0%   100%   512.05kB  5.67%  github.com/buger/goreplay/rlog.(*logWriter).ReadFile
         0     0%   100%  2368.33kB 26.21%  main.(*RAWInput).listen
         0     0%   100%  2368.33kB 26.21%  main.InitPlugins
         0     0%   100%  2368.33kB 26.21%  main.NewRAWInput
(pprof) root@sns-ads-service06:~/pprof#

top会列出5个统计数据:

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

3,list命令:查看某个函数的代码,以及该函数每行代码的指标信息,如果函数名不明确,会进行模糊匹配,

list   {分析的方法}

(pprof) list raw_socket_listener.NewListener
Total: 12.36MB
ROUTINE ======================== github.com/buger/goreplay/raw_socket_listener.NewListener in /go/src/goreplay/raw_socket_listener/listener.go
    2.85MB     2.85MB (flat, cum) 23.08% of Total
         .          .    112:// NewListener creates and initializes new Listener object
         .          .    113:func NewListener(addr string, port string, engine int, trackResponse bool, expire time.Duration, bpfFilter string, timestampType string, bufferSize int, overrideSnapLen bool, immediateMode bool, inputOverrideSnapLen int, memeryLimitSwitch bool, memeryLimit float64) (l *Listener) {
         .          .    114:	l = &Listener{}
         .          .    115:
         .          .    116:	l.packetsChan = make(chan *packet, 10000)
  553.04kB   553.04kB    117:	l.messagesChan = make(chan *TCPMessage, 10000)
         .          .    118:	l.quit = make(chan bool)
         .          .    119:	l.readyCh = make(chan bool, 1)
         .          .    120:	//pyrl add
    2.31MB     2.31MB    121:	l.thriftCh = make(chan []byte, 100000)
         .          .    122:	l.percentage = mycfg.GetGcfg().Percentage
         .          .    123:	l.rlogAppName = mycfg.GetGcfg().AppName
         .          .    124:	l.rlw = rlog.NewRLogger(rlog.WriterConfig{
         .          .    125:		AppName: l.rlogAppName,
         .          .    126:		Async:   true,

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

(二)根据前后两次生成的图标进行内存使用情况的对比

通过对比可查看前后两个时段的内存变化。

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

(三)查看内存分配

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

这个命令其实就是把当前内存分配的详情文件抓了下来,本地会生成一个叫heap?debug=1的文件,看一看服务内存分配的具体情况,也可通过runtime.MemStats获取

具体文件内存自行产看

指标含义大致如下

以下指标可参考看runtime.MemStats中响应参数的说明
    Alloc      uint64 // 已申请且仍在使用的字节数
    TotalAlloc uint64 // 已申请的总字节数(已释放的部分也算在内)
    Sys        uint64 // 从系统中获取的字节数(下面XxxSys之和)虚拟内存
    Lookups    uint64 // 指针查找的次数
    Mallocs    uint64 // 申请内存的次数
    Frees      uint64 // 释放内存的次数
    // 主分配堆统计
    HeapAlloc    uint64 // 已申请且仍在使用的字节数
    HeapSys      uint64 // 从系统中获取的字节数
    HeapIdle     uint64 // 闲置span中的字节数
    HeapInuse    uint64 // 非闲置span中的字节数
    HeapReleased uint64 // 释放到系统的字节数
    HeapObjects  uint64 // 已分配对象的总个数
    // L低层次、大小固定的结构体分配器统计,Inuse为正在使用的字节数,Sys为从系统获取的字节数
    StackInuse  uint64 // 引导程序的堆栈
    StackSys    uint64
    MSpanInuse  uint64 // mspan结构体
    MSpanSys    uint64
    MCacheInuse uint64 // mcache结构体
    MCacheSys   uint64
    BuckHashSys uint64 // profile桶散列表
    GCSys       uint64 // GC元数据
    OtherSys    uint64 // 其他系统申请
    // 垃圾收集器统计
    NextGC       uint64 // 会在HeapAlloc字段到达该值(字节数)时运行下次GC
    LastGC       uint64 // 上次运行的绝对时间(纳秒)
    PauseTotalNs uint64
    PauseNs      [256]uint64 // 近期GC暂停时间的循环缓冲,最近一次在[(NumGC+255)%256]
    NumGC        uint32
    EnableGC     bool
    DebugGC      bool

(四) 查询goroutine相关信息

$ wget http://ip:admin_port/debug/pprof/goroutine?debug=1
$ wget http://ip:admin_port/debug/pprof/goroutine?debug=2

debug=1就是获取服务当前goroutine的数目和大致信息,debug=2获取服务当前goroutine的详细信息,分别在本地生成了goroutine?debug=1和goroutine?debug=2文件,

如果要直接在控制台打印,加参数“-O -”

例如:wget -O - http://localhost:6060/debug/pprof/goroutine?debug=1

debug=1

root@sns-ads-service06:/usr/bin# wget -O - http://localhost:6060/debug/pprof/goroutine?debug=1
--2022-04-16 03:52:55--  http://localhost:6060/debug/pprof/goroutine?debug=1
Resolving localhost (localhost)... ::1, 127.0.0.1
Connecting to localhost (localhost)|::1|:6060... connected.
HTTP request sent, awaiting response... 200 OK
Length: unspecified [text/plain]
Saving to: 'STDOUT'

-                                               [<=>                                                                                      ]       0  --.-KB/s               goroutine profile: total 19
5 @ 0x439d16 0x40852c 0x407f58 0x84e639 0x46a261
#	0x84e638	github.com/buger/goreplay/raw_socket_listener.(*Listener).sendMsg+0x58	/go/src/goreplay/raw_socket_listener/listener.go:176

4 @ 0x40545c 0x83b0cc 0x83f091 0x83f009 0x8374ed 0x8371ac 0x7bdf1a 0x850ab4 0x46a261
#	0x83b0cb	github.com/google/gopacket/pcap._Cfunc_pcap_wait+0x4b				_cgo_gotypes.go:877
#	0x83f090	github.com/google/gopacket/pcap.(*Handle).waitForPacket.func1+0x50		/go/src/goreplay/vendor/github.com/google/gopacket/pcap/pcap_unix.go:693

debug=2 获取 详细的gorountie信息

root@sns-ads-service06:/usr/bin# wget -O - http://localhost:6060/debug/pprof/goroutine?debug=2
--2022-04-16 03:50:29--  http://localhost:6060/debug/pprof/goroutine?debug=2
Resolving localhost (localhost)... ::1, 127.0.0.1
Connecting to localhost (localhost)|::1|:6060... connected.
HTTP request sent, awaiting response... 200 OK
Length: unspecified [text/plain]
Saving to: 'STDOUT'

-                                               [<=>                                                                                      ]       0  --.-KB/s               goroutine 164 [running]:
runtime/pprof.writeGoroutineStacks({0xb16a20, 0xc00010e1c0})
	/usr/local/go/src/runtime/pprof/pprof.go:693 +0x70
goroutine 98 [chan receive, 8 minutes]:
github.com/buger/goreplay/rlog.(*logWriter).runCacheWrite(0xc00011c000)
	/go/src/goreplay/rlog/writer.go:397 +0x7d
created by github.com/buger/goreplay/rlog.(*logWriter).initLogWriter
	/go/src/goreplay/rlog/writer.go:172 +0x15b

goroutine 99 [chan receive, 8 minutes]:
github.com/buger/goreplay/raw_socket_listener.(*Listener).sendMsg(0xc0000eaea0)
	/go/src/goreplay/raw_socket_listener/listener.go:176 +0x59
created by github.com/buger/goreplay/raw_socket_listener.NewListener
	/go/src/goreplay/raw_socket_listener/listener.go:130 +0x2fa

(五)命令行获取goroutine信息

root@sns-ads-service06:/usr/bin# go tool pprof http://localhost:6060/debug/pprof/goroutine
Fetching profile over HTTP from http://localhost:6060/debug/pprof/goroutine
Saved profile in /root/pprof/pprof.thriftcapture.goroutine.002.pb.gz
File: thriftcapture
Build ID: adb18152e548b18b1b789f8ed7f8ef4d989f6a30
Type: goroutine
Time: Apr 16, 2022 at 3:56am (UTC)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)

Saved profile in /root/pprof/pprof.thriftcapture.goroutine.002.pb.gz

同heap一样,会生成goroutine文件

进行前后对比

(go tool pprof -base pprof.thriftcapture.goroutine.001.pb.gz pprof.thriftcapture.goroutine.002.pb.gz)

root@sns-ads-service06:~/pprof# go tool pprof -base pprof.thriftcapture.goroutine.001.pb.gz  pprof.thriftcapture.goroutine.002.pb.gz
File: thriftcapture
Build ID: adb18152e548b18b1b789f8ed7f8ef4d989f6a30
Type: goroutine
Time: Apr 16, 2022 at 3:46am (UTC)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 0, 0% of 0 total
      flat  flat%   sum%        cum   cum%
(pprof)

(上图两个文件的对比,看来没有任何区别)

指标含义于heap相同

同样有三个命令可以用

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

持续更新中。。。