本人小白,刚开始接触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相同
同样有三个命令可以用
- top:显示正运行到某个函数goroutine的数量
- traces:显示所有goroutine的调用栈
- list:列出代码详细的信息。
持续更新中。。。
大家如果对文章还有疑问可以参考 参考文献内容,本文只介绍了自己在使用过程中的一些排查用到的命令。