写了一些代码,但是不知道性能是什么?怎么样?go提供了go test 和go tool 原生工具对go性能进行评估 ,本文尝试使用传说中的PProf分析下性能:
PProf包
net/http/pprof :采集程序(非 Server)的运行数据进行分析
runtime/pprof:采集 HTTP Server 的运行时数据进行分析
#其实net/http/pprof中只是使用runtime/pprof包来进行封装了一下,并在http端口上暴露出来
#服务进程
#我的go程序是用http包启动的web服务器,引入_ "net/http/pprof"包,在浏览器中使用[http://localhost:port/debug/pprof/](http://localhost:port/debug/pprof/)直接看到当前web服务的状态,包括CPU占用情况和内存使用
import (
"log"
"net/http"
)
func main() {
go func() {
log.Println(http.ListenAndServe(":8888", nil))
}()
// 其它
}
#应用程序
#pprof.StartCPUProfile和pprof.StopCPUProfile 分析内存情况
import (
"flag"
"log"
"os"
"runtime/pprof"
"testing"
)
var cpuprofile = flag.String("cpuprofile", "", "write cpu profile to file")
func Benchmark_PProf(b *testing.B) {
flag.Parse()
if *cpuprofile != "" {
f, err := os.Create(*cpuprofile)
if err != nil {
log.Fatal(err)
}
err = pprof.StartCPUProfile(f)
if err != nil {
panic("StartCPUProfile err")
}
defer pprof.StopCPUProfile()
}
}
运行程序的时候加一个--cpuprofile参数,比如fabonacci --cpuprofile=fabonacci.prof
这样程序运行的时候的cpu信息就会记录到XXX.prof中了。
首先 PProf可以做什么?
CPU profiling cpu分析,按照一定的频率100Hz(10ms)采集所监听的应用程序cpu(含寄存器)的使用情况,确定应用程序在主动消耗cpu周期时花费时间的位置
Memory Profiling 内存分析,在应用程序进行堆分配记录堆栈跟踪,用于监听当前和历史内存使用情况,以及检查内存泄漏。
Block Profiling 阻塞分析,记录goroutine 阻塞等待同步(包含定时器通道)的位置,默认不开启,需要调用 runtime.SetBlockProfileRate 进行设置
Mutex Profiling 互斥锁分析。报告互斥锁的竞争情况,默认不开启,需要调用 runtime.SetMutexProfileFraction 进行设置
我的是一个服务进程
#直接访问网页:
profile(CPU Profiling): $HOST/debug/pprof/profile,默认进行 30s 的 CPU Profiling,得到一个分析用的 profile 文件
allocs 查看过去所有内存分配样本,访问路径为 /debug/pprof/allocs
cmdline 当前程序命令行的完整调用路径
block(Block Profiling):$HOST/debug/pprof/block,查看导致阻塞同步的堆栈跟踪
goroutine:$HOST/debug/pprof/goroutine,查看当前所有运行的 goroutines 堆栈跟踪
heap(Memory Profiling): $HOST/debug/pprof/heap,查看活动对象的内存分配情况
mutex(Mutex Profiling):$HOST/debug/pprof/mutex,查看导致互斥锁的竞争持有者的堆栈跟踪
threadcreate:$HOST/debug/pprof/threadcreate,查看创建新OS线程的堆栈跟踪
一般在线上环境,为了网络安全,通常不会这么做。另外debug的访问方式是具有时效性的,在实际场景中,我们常常需要及时将当前状态下的 profile文件给存储下来,便于二次分析。
#通过终端访问
//在执行命令后,需要等待 60s (可以调整seconds的值) PProf 会进行 cpu Profiling , 结束后将默认进入PProf 的命令行交互模式,查看或者导出分析结果。
// 如果是以TLS方式启动的HTTP Server 那么在调用需要改成 go tool pprof https+insecure://localhost:6060/debug/pprof/profile?seconds=60
默认进入30秒的profile收集时间,每100Hz(10ms)采样一次,seconds修改采样时间为60S
go tool pprof http://localhost:8080/debug/pprof/profile?seconds=60
Saved profile in C:\Users\Administrator\pprof\pprof.samples.cpu.005.pb.gz
Type: cpu
Time: Aug 30, 2021 at 5:00pm (CST)
Duration: 30s, Total samples = 1.97s ( 6.57%)
Entering interactive mode (type "help" for commands, "o" for options)
//命令能够很快的拉取到结果。不需要采样等待, 需要注意的是 Type 这个选项默认是 inuse_space,实际上,它可以对多种内存情况进行分析
#inuse_space 分析应用常驻内存的占用情况
go tool pprof http://10.254.0.193:60007/debug/pprof/heap
heap堆分配采样
Saved profile in C:\Users\Administrator\pprof\pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.006.pb.gz
Type: inuse_space
Time: Aug 30, 2021 at 3:43pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top 10
flat flat% sum% cum cum%
370ms 18.78% 18.78% 370ms 18.78% runtime.stdcall1
flat:当前函数上运行耗时
flat%:函数自身占用的 CPU 运行耗时总比例
sum%:函数自身累积使用 CPU 总比例
cum:当前函数及其调用函数的运行总耗时
cum%:函数自身及其调用函数占 CPU 运行耗时总比例
最后一列为函数名称
#alloc_objects 分析应用程序的内存临时分配情况
go tool pprof -alloc_objects http://localhost:8080/debug/pprof/heap
Saved profile in C:\Users\Administrator\pprof\pprof.samples.cpu.006.pb.gz
#另外还有 inuse_objects 和 alloc_space 类别,分别对应查看每个函数的对象数量和分配的内存空间大小。
go tool pprof http://localhost:6060/debug/pprof/goroutine
Saved profile in C:\Users\Administrator\pprof\pprof.goroutine.001.pb.gz
Type: goroutine
Time: Aug 30, 2021 at 5:10pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)traces
Type: goroutine
Time: Aug 30, 2021 at 5:10pm (CST)
-----------+-------------------------------------------------------
12 runtime.gopark
runtime.chanrecv
runtime.chanrecv2
github.com/klauspost/compress/zstd.(*blockDec).startDecoder
#在查看goroutine 时可以使用traces命令,这个命令会打印出对应的所有调用栈,以及指标信息,通过这个命令我们可以很方便的查看整改调用链路有什么,分别在哪里使用了多岁个goroutine,并且通过分析可以知道谁才是真正的调用方,输出结果如下:
E:\Go\src\sevennine.coding.net\ProjectCode\GameServer>go tool pprof http://10.254.0.193:60007/debug/pprof/heap
Fetching profile over HTTP from http://10.254.0.193:60007/debug/pprof/heap
Saved profile in C:\Users\Administrator\pprof\pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.007.pb.gz
Type: inuse_space
Time: Aug 30, 2021 at 5:15pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) traces
Type: inuse_space
Time: Aug 30, 2021 at 5:15pm (CST)
-----------+-------------------------------------------------------
bytes: 48B
0 reflect.unsafe_NewArray
reflect.MakeSlice
encoding/asn1.parseSequenceOf
encoding/asn1.parseField
encoding/asn1.parseSequenceOf
encoding/asn1.parseField
encoding/asn1.UnmarshalWithParams
encoding/asn1.Unmarshal
crypto/x509.parseCertificate
crypto/x509.ParseCertificate
crypto/x509.extractSimpleChain
crypto/x509.(*Certificate).systemVerify
crypto/x509.(*Certificate).Verify
crypto/tls.(*Conn).verifyServerCertificate
crypto/tls.(*clientHandshakeState).doFullHandshake
crypto/tls.(*clientHandshakeState).handshake
#在调用 chan (通道)、sync.Mutex (同步锁)或者 time.Sleep() 时会造成阻塞
#需要特别注意的是 runtime.SetMutexProfileFraction(1) 语句,如果未来希望对互斥锁进行采集,则需要调用该方法设置采集频率,如果没有设置,或者设置数值小于0,则不进行采集
func init() {
runtime.SetMutexProfileFraction(1)
}
#接下里调用 go tool pprof 进行分析:
go tool pprof http://localhost:6060/debug/pprof/mutex
Saved profile in C:\Users\Administrator\pprof\pprof.contentions.delay.001.pb.gz
Type: delay
Time: Aug 30, 2021 at 5:20pm (CST)
No samples were found with the default sample value type.
Try "sample_index" command to analyze different sample values.
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)top
Showing top 10 nodes out of 26
flat flat% sum% cum cum%
29.38us 100% 100% 29.38us 100% sync.(*Mutex).Unlock
0 0% 100% 4.62us 15.72% database/sql.(*Rows).Close
0 0% 100% 4.62us 15.72% database/sql.(*Rows).Next
#调用 list命令 查看指定函数的代码情况 (包含特定的指标信息,如耗时)若函数名不明确,则默认对该函数名进行模糊匹配:
#从输出分析中可以看到引起互斥锁函数,以及锁开销的位置。
# 与 Mutex 的 runtime.SetMutexProfileFraction 语句类似,Block也需要调用 runtime.SetBlockProfileRate 语句进行设置,如果没有设置,或者设置数值小于0,则不进行采集
func init() {
runtime.SetMutexProfileFraction(1)
runtime.SetBlockProfileRate(1)
}
go tool pprof http://localhost:6060/debug/pprof/block
Saved profile in C:\Users\admin\pprof\pprof.contentions.delay.004.pb.gz
Type: delay
Time: Oct 13, 2020 at 12:35am (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 83.75us, 100% of 83.75us total
flat flat% sum% cum cum%
83.75us 100% 100% 83.75us 100% sync.(*Cond).Wait
(pprof)
# 也可以用 list 命令查看具体阻塞情况。调用方式和 Mutex Profiling 一样