如何使用 pprof 来定位现网 Golang 问题,已经是一名 Gopher 所需要掌握的必备技能了。我们在实际工作中也经常使用它来定位现网问题。网上有很多文章来描述 pprof 的使用,但是实际的线上使用场景,却和各个文章的描述的多少有些差异。 比如网上大部分文章都会告诉你,使用命令行打开 we
如何使用 pprof 来定位现网 Golang 问题,已经是一名 Gopher 所需要掌握的必备技能了。我们在实际工作中也经常使用它来定位现网问题。网上有很多文章来描述 pprof 的使用,但是实际的线上使用场景,却和各个文章的描述的多少有些差异。
比如网上大部分文章都会告诉你,使用命令行打开 web 端口,在浏览器打开 web 界面,接着告诉你如何在 web 界面查看整个服务情况。但实际情况是,我们的线上服务基本都是跑在 centos 操作系统中的,由于安全问题,对外,对办公网络不可能开放web 访问端口,更无从通过 web 界面查看服务情况,故此,web 界面在现网基本不可用。
网上还有一些文章告诉你,如何使用 go tool pprof 命令来交互式定位问题。但这里隐藏的前提就是需要安装 go 工具。但于我来说,这个是极其不方便的,我们的现网服务是使用镜像安装,而镜像中只会安装编译好的业务二进制文件,并不会安装 go 工具。除非我们使用运维权限来安装 go 命令。故此,我希望知道在无 go 工具的时候我能做些什么。
我实际使用的现网环境是什么样的呢?- k8s 上运行无状态的 centos7 操作系统的镜像,镜像中打包了所需要的二进制命令,除此之外,只安装了基础的 vi,curl 命令。
那么我寻求一种能不需要安装,很快分析出 Golang 性能问题的办法,故有此纪录。
首先,first of all,巧妇难为无米之炊,这个米就是你在服务中开启了一个 pprof 端口。我们的服务都是 web 类型的服务,提供 http,只需要引入一行代码即可。
import _ "net/http/pprof"
如果不是 web 服务的话,则除了引入上面的库之外,还需要开启一个 goroutine 来监听服务。
go func() {
log.Println(http.ListenAndServe("localhost:6060", nil))
}()
如此,在你的服务运行过程中,就能通过本地的 6060 端口来进行数据获取。有米之后,才能烹煮大餐。
pprof 是一个套餐,里面有不少餐食,而我们接下来要做的,则需要分析我们想定位的问题,比如我们想看下如下几个问题:
以上每个问题,我们都需要使用 pprof 套件中对应的工具来解决。
我们最常犯的问题是 goroutine 泄漏。在 Golang 里面,开启一个协程是这么容易,导致我们在很多地方会 go 一个函数出去,但是是否这些函数都按照预期回收了呢?我们这里就需要用到 pprof 里面的 goroutine 子命令来进行分析了。
在 go 中,分析 goroutine,我们并不需要安装 go tool 工具,pprof 端口提供我们直接使用 curl 命令进行定位的能力。这也是我最常用的方法。
首先我们需要明确,goroutine 的分布是一个状态值,是可以直接打印出来的,当前进程中有多少 goroutine,分别是由哪些函数来创建的。并不需要进行时间段采样。
curl -o goroutine.log localhost:6060/debug/pprof/goroutine?debug=1
这里的 debug=1 是用来表示输出的格式,它的值分别有 1/2和不填。
当填写debug=1 的时候,输出的是可读性文本,是一种按照函数栈聚类分析的结果文本:
goroutine profile: total 2065
933 @ 0x4492d6 0x415e4c 0x4158b8 0x153ddf1 0x159a61e 0x47aa41
# 0x153ddf0 github.com/Shopify/sarama.(*partitionProducer).dispatch+0x1b0 /root/go/pkg/mod/github.com/!shopify/[email protected]/async_producer.go:545
# 0x159a61d github.com/Shopify/sarama.withRecover+0x3d /root/go/pkg/mod/github.com/!shopify/[email protected]/utils.go:43
194 @ 0x4492d6 0x415e4c 0x4158b8 0x153f385 0x159a61e 0x47aa41
# 0x153f384 github.com/Shopify/sarama.(*asyncProducer).newBrokerProducer.func1+0x64 /root/go/pkg/mod/github.com/!shopify/[email protected]/async_producer.go:694
# 0x159a61d github.com/Shopify/sarama.withRecover+0x3d /root/go/pkg/mod/github.com/!shopify/[email protected]/utils.go:43
如以上文本,说明了当前进程总共启动了 2065 个 goroutine,其中列出了排名靠前的 2 个堆栈:
github.com/Shopify/sarama.(*partitionProducer).dispatch
创建了 933 个 goroutine,在预期内
github.com/Shopify/sarama.(*asyncProducer).newBrokerProducer.func1
创建了 194 个 goroutine,在预期内
这样分析前几个占用 goroutine 数最多的堆栈,就大概能知道业务进程是否有 goroutine 泄漏了。debug=1 也是我最常用的分析方式。
填写 debug=2 的时候,输出的也是可读性文本,但它的输出是按照 goroutine 分类的结果文本:
goroutine 34890598 [running]:
runtime/pprof.writeGoroutineStacks({0x2917520, 0xc002716c40})
/usr/go/src/runtime/pprof/pprof.go:693 +0x70
runtime/pprof.writeGoroutine({0x2917520, 0xc002716c40}, 0x0)
/usr/go/src/runtime/pprof/pprof.go:682 +0x2b
runtime/pprof.(*Profile).WriteTo(0x21ae7e0, {0x2917520, 0xc002716c40}, 0xc)
/usr/go/src/runtime/pprof/pprof.go:331 +0x14b
net/http/pprof.handler.ServeHTTP({0xc00b075ea1, 0xc000153000}, {0x2939d10, 0xc002716c40}, 0xc00b075e94)
/usr/go/src/net/http/pprof/pprof.go:253 +0x49a
net/http/pprof.Index({0x2939d10, 0xc002716c40}, 0xc007f8ce00)
/usr/go/src/net/http/pprof/pprof.go:371 +0x12e
net/http.HandlerFunc.ServeHTTP(0xc00428aa30, {0x2939d10, 0xc002716c40}, 0xc00b075eab)
/usr/go/src/net/http/server.go:2047 +0x2f
...
goroutine 1 [select, 6426 minutes]:
git.code.oa.com/my-go/server.(*Server).Serve(0xc000014cb0)
/root/go/pkg/mod/[email protected]/server/serve_unix.go:46 +0x3ae
main.main()
/data/__qci/root-workspaces/__qci-pipeline-251750-1/main.go:111 +0x4d6
goroutine 19 [syscall, 702 minutes]:
syscall.Syscall6(0xe8, 0x7, 0xc00020fbec, 0x7, 0xffffffffffffffff, 0x0, 0x0)
/usr/go/src/syscall/asm_linux_amd64.s:43 +0x5
golang.org/x/sys/unix.EpollWait(0x2, {0xc00020fbec, 0x2, 0xc0091c98c0}, 0xc00020fcb4)
/root/go/pkg/mod/golang.org/x/[email protected]/unix/zsyscall_linux_amd64.go:56 +0x58
github.com/fsnotify/fsnotify.(*fdPoller).wait(0xc000122300)
/root/go/pkg/mod/github.com/fsnotify/[email protected]/inotify_poller.go:86 +0x7d
github.com/fsnotify/fsnotify.(*Watcher).readEvents(0xc00010e690)
/root/go/pkg/mod/github.com/fsnotify/[email protected]/inotify.go:192 +0x2b0
created by github.com/fsnotify/fsnotify.NewWatcher
/root/go/pkg/mod/github.com/fsnotify/[email protected]/inotify.go:59 +0x1c7
这个文本非常长,它把每个 goroutine 的堆栈信息,运行状态,运行时长都列了出来。如上图,列了 3 个 gorouine ,
debug=2 的方式最有用的就是 goroutine 的运行时长和更详细的堆栈信息,在使用 debug=1 定位出可疑堆栈的时候,用堆栈的函数去 debug=2 中找,能大概看出来它已经启动多久,更具体的堆栈有哪些,当前是卡在哪个系统函数中,能更快定位问题。
这两种 debug 的值是可以直接在控制台通过 curl 和 vi进行查看的,对于现网非常方便的。如果不指定 debug ,输出的 goroutine.log 打开就是一种二进制乱码,它就只能通过 go tool pprof 工具打开,这样在没有go tool 的环境中,就需要想办法安装 go 工具,或者下载到有 go 工具的环境才能阅读了。当然使用 go tool 工具很麻烦,但是它能看出更多的信息。
curl -o goroutine.log localhost:11014/debug/pprof/goroutine
go tool pprof goroutine.log
进入控制台,我们最常使用的就是
top [100]
命令,比如
top 100
(pprof) top100
Showing nodes accounting for 2027, 99.75% of 2032 total
Dropped 204 nodes (cum <= 10)
flat flat% sum% cum cum%
2027 99.75% 99.75% 2027 99.75% runtime.gopark
0 0% 99.75% 186 9.15% bufio.(*Reader).Peek
0 0% 99.75% 19 0.94% bufio.(*Reader).Read
0 0% 99.75% 187 9.20% bufio.(*Reader).fill
0 0% 99.75% 32 1.57% my-go/kafka.(*singleConsumerHandler).ConsumeClaim
0 0% 99.75% 16 0.79% my-go/transport.(*serverTransport).servePacket
0 0% 99.75% 16 0.79% my-go/transport.(*serverTransport).serveUDP
0 0% 99.75% 16 0.79% github.com/Shopify/sarama.(*Broker).Fetch
0 0% 99.75% 16 0.79% github.com/Shopify/sarama.(*Broker).readFull
0 0% 99.75% 62 3.05% github.com/Shopify/sarama.(*Broker).responseReceiver
0 0% 99.75% 16 0.79% github.com/Shopify/sarama.(*Broker).sendAndReceive
0 0% 99.75% 168 8.27% github.com/Shopify/sarama.(*asyncProducer).newBrokerProducer.func1
0 0% 99.75% 16 0.79% github.com/Shopify/sarama.(*brokerConsumer).fetchNewMessages
0 0% 99.75% 17 0.84% github.com/Shopify/sarama.(*brokerConsumer).subscriptionConsumer
0 0% 99.75% 17 0.84% github.com/Shopify/sarama.(*brokerConsumer).subscriptionManager
0 0% 99.75% 168 8.27% github.com/Shopify/sarama.(*brokerProducer).run
0 0% 99.75% 16 0.79% github.com/Shopify/sarama.(*bufConn).Read
0 0% 99.75% 32 1.57% github.com/Shopify/sarama.(*consumerGroupSession).consume
0 0% 99.75% 33 1.62% github.com/Shopify/sarama.(*consumerGroupSession).consume.func1
0 0% 99.75% 33 1.62% github.com/Shopify/sarama.(*consumerGroupSession).consume.func2
0 0% 99.75% 33 1.62% github.com/Shopify/sarama.(*partitionConsumer).dispatcher
0 0% 99.75% 33 1.62% github.com/Shopify/sarama.(*partitionConsumer).responseFeeder
0 0% 99.75% 933 45.92% github.com/Shopify/sarama.(*partitionProducer).dispatch
0 0% 99.75% 33 1.62% github.com/Shopify/sarama.newConsumerGroupClaim.func1
0 0% 99.75% 33 1.62% github.com/Shopify/sarama.newConsumerGroupSession.func1
0 0% 99.75% 32 1.57% github.com/Shopify/sarama.newConsumerGroupSession.func2
0 0% 99.75% 1453 71.51% github.com/Shopify/sarama.withRecover
这个 top 命令其实带的信息就值得好好琢磨琢磨了。
Showing nodes accounting for 2027, 99.75% of 2032 total
这里的 top 100 已经展示了所有 2032 个 goroutine 中的 2027 个了,占比 99.75%。所以通过这个,我们就能知道,top 100 就已经很够分析了,可以不同再扩大 top 的个数了。
但是即使是 top100,我们全部展示也太大了,所以我们需要舍弃一些函数,
Dropped 204 nodes (cum <= 10)
告诉我们,以下列表舍弃了 cum <= 10 的函数,具体 cum 值是什么意思呢,下面一起说。
flat, sum, cum 这三个值在 pprof 的各个工具中都会出现,要知道他们的意思才能进一步分析:
上栗子:我现在有个调用链,funcA -> funcB -> funcC。且在 funcA/B/C 中,除了函数调用之外,他们函数自身也会各自创建 goroutine,我们假设 funcA/B/C 各自函数创建的 goroutine 数为 1/2/3。
那么对于 funcB 而言,它的 flat 指的是 funcB 这个函数自己创建的数量,为 2。而 sum 表示的是 funB 这个函数,及调用它的函数 funcA 共同创建的 goroutine 的数量,为 1+2 =3。而 cum 表示的是 funB 和它调用的函数 funcC 创建的 goroutine 的数量,为 2+3 = 5。
而每个函数的这三个指标在所有函数中的占比就为三个指标对应的百分比:flat% sum% cum%。
理解了这些,我们就能理解为什么在第一列的gopark 是那样的数值了。
flat flat% sum% cum cum%
2027 99.75% 99.75% 2027 99.75% runtime.gopark
这是一个最底层函数,基本所有的 goroutine 创建之后都会调用它,所以它自身创建的 goroutine 数为 flat: 2027,且它没有下层调用,所以它的cum 也为 2027。
再看一个第二列的数值:
flat flat% sum% cum cum%
0 0% 99.75% 186 9.15% bufio.(*Reader).Peek
bufio.(*Reader).Peek
这个函数自身不创建 goroutine(flat = 0),但是调用它的函数创建的 goroutine 占比 ( 99.75% ),它的下层调用创建了 186 个 goroutine,占比 9.15%。
所以我们要分析 goroutine 泄漏的时候要看哪个值呢?- 对的,cum。
找到 cum 占比最大的函数,这里一般我们都会查找非系统调用函数,(因为系统调用函数不大可能有问题),那么我们就知道我们的哪个应用函数存在 goroutine 泄漏。
这里另外说下,有的文章说可以下一步用 list + 函数名 的方式来列出最占用资源的行数。行,当然行,但是它的使用情景更为苛刻了 - 需要在现网机器安装源码+依赖库。而这个在现网环境基本是不可能的,所以这个list 命令在实际分析中我自己是很少用到的。
如果我们是一个 cpu 暴涨的问题,我们就需要使用pprof 套件中的 profile 工具来定位出哪个函数占用 cpu 比较多。
这里我们需要明确一下:
我们说是要定位一个程序的 cpu 消耗问题,但是这里其实隐藏了一个时间段概念,即:“我们要定位什么时间段内的 cpu 消耗”? - 这里当然无法定位过去时间的 cpu 消耗,我们只能定位从运行时间开始一段时间内的 cpu 消耗,即“从现在开始的 30s 作为取样样本,来分析这段时间内的 cpu 耗时分布”。所以我们需要给 pprof 端口下命令,来定位抓取 30s 内的消耗,同样,我们使用 curl 命令即可。
curl -o profile.log localhost:6060/debug/pprof/profile?seconds=30
这里的两个参数,seconds - 指定样本时间,很好理解。而这里输出的 profile.log 打开是一种二进制乱码,profile 是没有 debug 参数的,它只能通过 go tool pprof 工具打开。如果我们安装 go 工具,或者下载 profile.log 到有 go 工具的环境,我们才能阅读。- 这里就是比较麻烦的一点了。
不过所幸,阅读的方法同 goroutine 的 top 命令类似,唯一不同的是,这里的资源换成了函数消耗的 cpu 时间。
(pprof) top100
Showing nodes accounting for 4.26s, 79.92% of 5.33s total
Dropped 370 nodes (cum <= 0.03s)
Showing top 100 nodes out of 395
flat flat% sum% cum cum%
0.49s 9.19% 9.19% 0.73s 13.70% runtime.scanobject
0.43s 8.07% 17.26% 0.43s 8.07% runtime.futex
0.32s 6.00% 23.26% 0.35s 6.57% syscall.Syscall
0.23s 4.32% 27.58% 0.53s 9.94% runtime.mallocgc
0.19s 3.56% 31.14% 0.19s 3.56% runtime.epollwait
0.13s 2.44% 33.58% 0.13s 2.44% runtime.greyobject
0.13s 2.44% 36.02% 0.14s 2.63% runtime.heapBitsSetType
0.13s 2.44% 38.46% 0.13s 2.44% runtime.memmove
0.12s 2.25% 40.71% 0.12s 2.25% runtime.findObject
0.12s 2.25% 42.96% 0.12s 2.25% runtime.usleep
0.10s 1.88% 44.84% 0.80s 15.01% runtime.findrunnable
0.10s 1.88% 46.72% 0.26s 4.88% runtime.stealWork
0.08s 1.50% 48.22% 0.08s 1.50% [libc-2.28.so]
0.08s 1.50% 49.72% 0.11s 2.06% runtime.mapaccess2
0.08s 1.50% 51.22% 0.08s 1.50% runtime.memclrNoHeapPointers
0.06s 1.13% 52.35% 0.11s 2.06% go.uber.org/zap/zapcore.(*jsonEncoder).tryAddRuneSelf
0.05s 0.94% 53.28% 0.19s 3.56% google.golang.org/protobuf/internal/impl.(*MessageInfo).unmarshalPointer
0.05s 0.94% 54.22% 0.06s 1.13% runtime.lock2
0.05s 0.94% 55.16% 0.15s 2.81% runtime.mapassign_faststr
0.05s 0.94% 56.10% 0.05s 0.94% runtime.step
如何分析?如果你看了 goroutine 那节,就知道这是一个套路了,如果没有看,往上翻。 - 1 看 cum 值,2 过滤出非系统函数调用,第一个占用最大的应用函数,就是目标函数了,然后分析代码,有没有什么 for 死循环,有没有什么耗 cpu 的行为,就是它了。
在没有 goroutine 泄漏的前提下,内存为什么占用这么大呢?我们需要 pprof 套件中的两个工具,allocs 和 heap。
为什么有两个呢?它们两个的差别就是allocs 代表的是某个函数历史创建的所有的内存(包括已经回收了的),而 heap 代表的是当前活跃的内存占用对象。所以我们能看到 allocs 中的数值会比 heap 大了非常多,一般我们使用 heap 比较多。
他们两个命令都有 debug 参数,但是 debug 参数只能为 1 或者没有。同 goroutine 命令一样,没有 debug 参数就只能通过 go tool 来分析,会麻烦些。
我们这里分析一个下 debug=1 的可读性文本:
curl -o allocs1.log localhost:6606/debug/pprof/allocs?debug=1
这里说一下,allocs 和 heap 两个命令使用 debug=1 的参数,显示的内容其实都是一样的,可读性文本里面不仅包含了当前活跃的内存信息,也包含了历史创建的内存信息。比如下面这个展示:
heap profile: 169: 18537048 [35672473: 126318298296] @ heap/1048576
1: 1810432 [1: 1810432] @ 0x41dbee 0x41d99c 0x1b75345 0x456203 0x456151 0x456151 0x456151 0x448ec6 0x47aa41
# 0x1b75344 github.com/mozillazg/go-pinyin.init+0x3c4 /root/go/pkg/mod/github.com/mozillazg/[email protected]/pinyin_dict.go:5
# 0x456202 runtime.doInit+0x122 /usr/go/src/runtime/proc.go:6498
# 0x456150 runtime.doInit+0x70 /usr/go/src/runtime/proc.go:6475
# 0x456150 runtime.doInit+0x70 /usr/go/src/runtime/proc.go:6475
# 0x456150 runtime.doInit+0x70 /usr/go/src/runtime/proc.go:6475
# 0x448ec5 runtime.main+0x1e5 /usr/go/src/runtime/proc.go:238
第一行
169: 18537048 [35672473: 126318298296]
告诉我们,这个进程目前活跃 169 个对象,占用字节数18537048,历史有过 35672473 个对象,占用字节数 126318298296。 1048576 表示内存采样的频率,默认采样频率是512kb 。这里采样频率是两倍的内存采样频率(1024 x 1024)。
第二行
1: 1810432 [1: 1810432]
告诉我们,下面这个堆栈活跃 1 个对象,占用字节数 1810432,历史只有过 1 个对象,占用字节数 1810432。
但是实话说,分析内存如果用这个 curl 的方式,会看的很累,因为它的排序并没有任何太多意义,比如占用最大内存的,可能是非常合理的,要看到后面几名才能知道哪个占用内存大不合理。
还是通过 go tool 工具来查看top 更为快捷:
以下是 allocs 命令的 top
(pprof) top10
Showing nodes accounting for 8273GB, 47.42% of 17444.69GB total
Dropped 2963 nodes (cum <= 87.22GB)
Showing top 10 nodes out of 267
flat flat% sum% cum cum%
1948.96GB 11.17% 11.17% 1948.96GB 11.17% go.uber.org/zap/buffer.(*Buffer).AppendByte (inline)
1260.22GB 7.22% 18.40% 1260.22GB 7.22% my-go/codec.MetaData.Clone
895.47GB 5.13% 23.53% 3649.40GB 20.92% go.uber.org/zap/zapcore.(*ioCore).Write
894.80GB 5.13% 28.66% 987.35GB 5.66% google.golang.org/protobuf/internal/encoding/text.(*Encoder).WriteName (inline)
813.76GB 4.66% 33.32% 813.76GB 4.66% go.uber.org/zap/internal/bufferpool.init.func1
780.93GB 4.48% 37.80% 3200.55GB 18.35% fmt.Sprintf
以下是 heap 命令的 top
Showing nodes accounting for 47.06MB, 50.44% of 93.30MB total
Showing top 10 nodes out of 487
flat flat% sum% cum cum%
12.93MB 13.86% 13.86% 12.93MB 13.86% google.golang.org/protobuf/internal/strs.(*Builder).AppendFullName
9.06MB 9.71% 23.57% 17.50MB 18.75% google.golang.org/protobuf/internal/filedesc.(*Message).unmarshalFull
6.11MB 6.54% 30.12% 6.11MB 6.54% github.com/rcrowley/go-metrics.newExpDecaySampleHeap
3.50MB 3.75% 33.87% 6.50MB 6.97% my-go/pkg/model/pb.v2ServiceInstancesToV1
3.01MB 3.22% 37.09% 3.01MB 3.22% github.com/Shopify/sarama.(*asyncProducer).newPartitionProducer
3MB 3.22% 40.31% 3MB 3.22% my-go/pkg/model/pb.v2StringToV1WrapperString (inline)
从这里也能看出,alloc 的数值比 heap 大了不少,相比之下,heap 命令对于分析当前服务内存占用更有作用。
pprof 套件中还有很多工具,有哪些工具呢?不用费心去记,直接 curl 也能看出来。
curl http://localhost:6606/debug/pprof/
输出的 html 有如下的有用信息:
204775 allocs
0 block
0 cmdline
1882 goroutine
204775 heap
0 mutex
0 profile
18 threadcreate
0 trace
allocs: A sampling of all past memory allocations
block: Stack traces that led to blocking on synchronization primitives
cmdline: The command line invocation of the current program
goroutine: Stack traces of all current goroutines
heap: A sampling of memory allocations of live objects. You can specify the gc GET parameter to run GC before taking the heap sample.
mutex: Stack traces of holders of contended mutexes
profile: CPU profile. You can specify the duration in the seconds GET parameter. After you get the profile file, use the go tool pprof command to investigate the profile.
threadcreate: Stack traces that led to the creation of new OS threads
trace: A trace of execution of the current program. You can specify the duration in the seconds GET parameter. After you get the trace file, use the go tool trace command to investigate the trace.
让 Claude 帮我们解释下:
这些是 Go (golang)
pprof
包提供的不同的分析工具,每个工具都有特定的目的,用于分析和调试 Go 应用程序的性能问题。以下是每个工具的功能:
seconds
GET 参数指定分析的持续时间。
seconds
GET 参数指定追踪的持续时间。
这些工具对于理解和优化 Go 应用程序的性能非常有价值,特别是在处理复杂的并发系统或内存密集型工作负载时。
其他几个工具我基本上很少使用了,等有用的时候再记录吧,或许一直也用不到,那么正应了那句古话:书到不用时方嫌多。
https://mp.weixin.qq.com/s/_MWtrXYWm5pzT8Rt3r_YDQ
https://www.cnblogs.com/hobbybear/p/17292713.html
https://go.dev/doc/diagnostics
https://jvns.ca/blog/2017/09/24/profiling-go-with-pprof/
https://segmentfault.com/a/1190000016412013
https://segmentfault.com/a/1190000019222661
https://blog.wolfogre.com/posts/go-ppof-practice/
小园丁追剧 最新版 1.4 20.96 MB
下载
湘ICP备2022002427号-10湘公网安备:43070202000427号
© 2013~2019 haote.com 好特网