往期好文推荐 ⭐️⭐️⭐️:
# golang pprof 监控系列(1) —— go trace 统计原理与使用
# golang pprof监控系列(2) —— memory,block,mutex 使用
# golang pprof 监控系列(3) —— memory,block,mutex 统计原理
# golang pprof 监控系列(4) —— goroutine thread 统计原理
# golang pprof 监控系列(5) —— cpu 占用率 统计原理
大家好,我是蓝胖子,说到golang的性能分析,不得不提的就是其自身拥有的pprof,它提供了从cpu,内存,阻塞情况,协程,线程,乃至程序运行轨迹trace的分析,可以说相当强大了。
今天我将会用较长的篇幅阐述 应该如何使用pprof工具来 对cpu,内存,阻塞情况,协程,线程 这几个维度去进行分析。
其实总结出来Golang pprof的使用方式,可以用下面的思维导图来表示,
要么在程序中通过http接口的方式暴露相应的pprof的采集控制界面,要么就是在程序中通过代码开启对应指标的采集样本功能,采集一段时间的样本后生成二进制文件,最后通过 go tool pprof
命令去对样本的数据进行分析。
分析的方式也有两种,
- 通过命令行开启一个交互终端
- 通过浏览器将二进制文件的信息展示出来
我们可以通过下述的代码通过http接口的方式暴露相应的pprof的采集控制界面,
import (
"log"
"net/http"
"net/http/pprof"
"time")
func main() {
mux := http.NewServeMux()
mux.HandleFunc("/debug/pprof/", pprof.Index)
mux.HandleFunc("/debug/pprof/cmdline", pprof.Cmdline)
mux.HandleFunc("/debug/pprof/profile", pprof.Profile)
mux.HandleFunc("/debug/pprof/symbol", pprof.Symbol)
mux.HandleFunc("/debug/pprof/trace", pprof.Trace)
go func() { log.Fatal(http.ListenAndServe(":8080", mux)) }()
time.Sleep(time.Hour)
}
接着访问下http://localhost:8080/debug/pprof/ 便会出现各种维度指标,可以点击进去查看具体的指标信息。如下所示,
接下来我们来分析下各个指标在 http接口或者生成的二进制文件 输出的各种信息究竟代表什么含义。
在下面的分析中我会分别的从http接口暴露指标的方式和二进制文件的方式分别介绍如何看懂各种指标的输出信息。
cpu
cpu在http接口暴露的分析界面中有个profile
的链接,点击后,应用程序会采集30s的cpu运行信息后然后生成一个二进制文件,所以本质上对cpu的分析都是通过一个二进制文件进行的。
除了上述提到http接口暴露出cpu指标外,我们还可以通过下面的代码,在程序中显示的开启cpu指标的采集。在这个例子中,我通过busyCpu 方法不断的进行加法运算来模拟频繁的cpu操作。
import (
"github.com/pkg/profile"
"log"
"os"
"os/signal"
"syscall")
func main() {
p := profile.Start(profile.CPUProfile,
profile.ProfilePath("profile"),
profile.NoShutdownHook,
)
defer p.Stop()
go busyCpu()
c := make(chan os.Signal, 1)
signal.Notify(c, syscall.SIGINT, syscall.SIGTERM)
defer signal.Stop(c)
<-c
}
func busyCpu() {
i := uint(1000000)
for {
log.Println("sum number", i, Add(i, i+1))
i++
}
}
func Add(a, b uint) uint {
return a + b
}
启动终端分析
在得到二进制文件后,我们可以使用如下命令来启动一个交互终端来分析cpu的使用情况,
go tool pprof cpuprofile/cpu.pprof
输入top
命令得到如下结果
(base) ➜ cpu go tool pprof cpuprofile/cpu.pprof
Type: cpu
Time: Mar 4, 2024 at 3:14pm (CST)
Duration: 4.35s, Total samples = 200ms ( 4.60%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 200ms, 100% of 200ms total
Showing top 10 nodes out of 16
flat flat% sum% cum cum%
190ms 95.00% 95.00% 190ms 95.00% syscall.syscall
10ms 5.00% 100% 10ms 5.00% runtime.pthread_cond_signal
0 0% 100% 190ms 95.00% internal/poll.(*FD).Write
0 0% 100% 190ms 95.00% internal/poll.ignoringEINTRIO (inline)
0 0% 100% 190ms 95.00% log.(*Logger).output
0 0% 100% 190ms 95.00% log.Println (inline)
0 0% 100% 190ms 95.00% main.busyCpu
0 0% 100% 190ms 95.00% os.(*File).Write
0 0% 100% 190ms 95.00% os.(*File).write (inline)
0 0% 100% 10ms 5.00% runtime.exitsyscallfast.func1
每个列的含义如下:
flat
:函数自身的运行耗时(排除了子函数的调用耗时)
flat%
:flat运行耗时占用总的采集样本的时间和的比例,这里所有节点运行的flat时间和为200ms。
sum%
:命令行返回结果中函数自身和其之上的函数运行的flat时间占所有采集样本时间总和的比例。
cum
:当前函数和其子函数的调用耗时总的运行时间
cum%
:cum耗时占总的采集样本的时间和的比例。
分析中可以看出主要是打印日志占用了比较大的cpu。
在命令行中可以输入svg,来输出cpu性能剖析的profile 图。
(pprof) svg
Generating report in profile001.svg
图中显示了函数的调用关系,函数框中显示了函数自身的运行时长flat和其自身及其子函数运行时长cum,箭头上的时间则是其子函数的cum运行时长,时间越大,箭头越粗。
将二进制文件信息输出到浏览器上
可以通过如下命令来启动浏览器查看cpu使用情况,
go tool pprof -http=:8082 cpuprofile/cpu.pprof
火焰图分析性能问题
通过web界面,我们除了按刚才的top和调用耗时图像外,甚至还能通过火焰图的方式,来查看cpu调用耗时,火焰图上,函数的调用顺序是从上往下,函数占用cpu越长,那么在火焰图上的区块就会越大
。 火焰图中显示的是cum值。
peek
除了像top那样输出函数的耗时情况,还会输出调用函数和被调用函数,调用顺序从上到下。
source
在web界面可以通过source视图去查看函数节点的耗时以及它的子调用函数中耗时的地方,第一栏时间是flat耗时,第二栏时间是cum耗时。 耗时百分比是cum耗时占样本总和的百分比。
内存
http接口暴露的控制台查看
通过点击heap
或者allocs
链接可以查看内存的分配情况,它们的输出都是一致的,
heap profile: 7: 5536 [110: 2178080] @ heap/1048576
2: 2304 [2: 2304] @ 0x100d7e0ec 0x100d7ea78 0x100d7f260 0x100d7f78c 0x100d811cc 0x100d817d4 0x100d7d6dc 0x100d7d5e4 0x100daba20
# 0x100d7e0eb runtime.allocm+0x8b /Users/lanpangzi/goproject/src/go/src/runtime/proc.go:1881
# 0x100d7ea77 runtime.newm+0x37 /Users/lanpangzi/goproject/src/go/src/runtime/proc.go:2207
# 0x100d7f25f runtime.startm+0x11f /Users/lanpangzi/goproject/src/go/src/runtime/proc.go:2491
# 0x100d7f78b runtime.wakep+0xab /Users/lanpangzi/goproject/src/go/src/runtime/proc.go:2590
# 0x100d811cb runtime.resetspinning+0x7b /Users/lanpangzi/goproject/src/go/src/runtime/proc.go:3222
# 0x100d817d3 runtime.schedule+0x2d3 /Users/lanpangzi/goproject/src/go/src/runtime/proc.go:3383
# 0x100d7d6db runtime.mstart1+0xcb /Users/lanpangzi/goproject/src/go/src/runtime/proc.go:1419
# 0x100d7d5e3 runtime.mstart0+0x73 /Users/lanpangzi/goproject/src/go/src/runtime/proc.go:1367
# 0x100daba1f runtime.mstart+0xf /Users/lanpangzi/goproject/src/go/src/runtime/asm_arm64.s:117
下面来讲下网页输出内容的含义
heap profile: 7: 5536 [110: 2178080] @ heap/1048576
输出的第一行含义分别是:
7 代表 当前活跃的对象个数
5536 代表 当前活跃对象占用的字节数
110 代表 所有(包含历史的对象)对象个数
2178080 代表 所有对象(包含历史的对象)占用的对象字节数
1048576 控制了内存采样的频率,1048576 是两倍的内存采样频率的大小,默认采样频率是512kb 即平均每512kb就会采样一次,注意这个值512kb不是绝对的达到512kb就会进行采样,而是从一段时间内的采样来看的一个平均值。
接下来就是函数调用堆栈信息,来看第一行
2: 2304 [2: 2304] @ 0x100d7e0ec 0x100d7ea78 0x100d7f260 0x100d7f78c 0x100d811cc 0x100d817d4 0x100d7d6dc 0x100d7d5e4 0x100daba20
从左往右看:
2 代表 在该函数栈上当前活跃的对象个数
2304 代表 在该函数栈上当前活跃的对象所占用的字节数
方括号内的2 代表 在该函数栈上所有(包含历史的对象)对象个数
方括号内的2304 代表 在该函数栈上所有(包含历史的对象)对象所占用的字节数
然后是栈上pc寄存器的值。再往后就是具体的栈函数名信息了。
通过二进制文件查看
我们可以使用如下代码生成一个关于内存使用情况的二进制profile文件,下述代码中我用
allocMem 函数不断对一个字节数组进行append操作来模拟内存不断增大的情况。
package main
import (
"github.com/pkg/profile"
"log"
"os"
"os/signal"
"syscall"
"time")
func main() {
p := profile.Start(profile.MemProfile,
profile.ProfilePath("profile"),
profile.NoShutdownHook,
)
defer p.Stop()
go allocMem()
c := make(chan os.Signal, 1)
signal.Notify(c, syscall.SIGINT, syscall.SIGTERM)
defer signal.Stop(c)
<-c
}
func allocMem() {
buf := []byte{}
mb := 1024 * 1024
for {
buf = append(buf, make([]byte, mb)...)
log.Println("total allocated memory", len(buf))
time.Sleep(time.Second)
}
}
生成的二进制文件,和cpu分析一致,可以通过启动交互终端或者web浏览器去进行查看,所以启动终端的方式我这里就暂时略去了, 讲讲不同点, 针对于内存,pprof在web 浏览器界面提供了几个维度去分析。
inuse_space
: 正在使用,尚未释放的空间
inuse_object
: 正在使用,尚未释放的对象
alloc_space
: 所有分配的空间,包含已释放的
alloc_objects
: 所有分配的对象,包含已释放的
拿inuse_object
举例,性能剖析图是这样的,箭头显示了正在使用的对象个数,其中 main.allocMem函数自身有一个4MB多的对象,其子函数有4个对象
我们可以根据source
选项也能得到同样的分析结果,
block
block可用于分析程序锁mutex,select ,channel通道, wait group 的阻塞行为。
但是block通常是关闭的,需要通过下面代码进行开启,
runtime.SetBlockProfileRate(1)
其中,SetBlockProfileRate 的参数名为rate,rate不同,对block事件的采样频率不同
1
代表 始终对阻塞事件进行采样<= 0
代表关闭阻塞事件的采样- 除了上述两种情况,SetBlockProfileRate 的参数传递的将会是一个纳秒值。
如果阻塞的时间大于了rate值则直接进行采样,如果阻塞的时间小于rate,那么阻塞事件将会有(阻塞时间)/rate 的可能性被采集到。
标签:profile,src,main,pprof,Golang,字长,go,runtime From: https://www.cnblogs.com/hobbybear/p/18059425