路漫漫其修远兮
吾将上下而求索

go学习:pprof基础使用

前言

如果要说在 golang 开发过程进行性能调优,pprof 一定是一个大杀器般的工具。但在网上找到的教程都偏向简略,难寻真的能应用于实战的教程。这也无可厚非,毕竟 pprof 是当程序占用资源异常时才需要启用的工具,而我相信大家的编码水平和排场问题的能力是足够高的,一般不会写出性能极度堪忧的程序,且即使发现有一些资源异常占用,也会通过排查代码快速定位,这也导致 pprof 需要上战场的机会少之又少。即使大家有心想学习使用 pprof,却也常常相忘于江湖。

既然如此,那我就送大家一个性能极度堪忧的“炸弹”程序吧!

这程序没啥正经用途缺极度占用资源,基本覆盖了常见的性能问题。本文就是希望读者能一步一步按照提示,使用 pprof 定位这个程序的的性能瓶颈所在,借此学习 pprof 工具的使用方法。

因此,本文是一场“实验课”而非“理论课”,请读者腾出时间,脚踏实地,一步一步随实验步骤进行操作,这会是一个很有趣的冒险,不会很无聊,希望你能喜欢。

实验准备

这里假设你有基本的 golang 开发功底,拥有 golang 开发环境并配置了 $GOPATH,能熟练阅读简单的代码或进行简单的修改,且知道如何编译运行 golang 程序。此外,需要你大致知道 pprof 是干什么的,有一个基本印象即可。

此外由于你需要运行一个“炸弹”程序,请务必确保你用于做实验的机器有充足的资源,你的机器至少需要:

  • 2 核 CPU;

  • 2G 内存。

注意,以上只是最低需求,你的机器配置能高于上述要求自然最好。实际运行“炸弹”时,你可以关闭电脑上其他不必要的程序,甚至 IDE 都不用开,我们的实验操作基本上是在命令行里进行的。

此外,务必确保你是在个人机器上运行“炸弹”的,能接受机器死机重启的后果(虽然这发生的概率很低)。请你务必不要在危险的边缘试探,比如在线上服务器运行这个程序。

可能说得你都有点害怕了,为打消你顾虑,我可以剧透一下“炸弹”的情况,让你安心:

  • 程序会占用约 2G 内存;

  • 程序占用 CPU 最高约 100%(总量按“核数 * 100%”来算);

  • 程序不涉及网络或文件读写;

  • 程序除了吃资源之外没有其他危险操作。

且程序所占用的各类资源,均不会随着运行时间的增长而增长,换句话说,只要你把“炸弹”启动并正常运行了一分钟,就基本确认安全了,之后即使运行几天也不会有更多的资源占用,除了有点费电之外。

获取“炸弹”

go-pprof-practice.tar.gz

我们可以简单看一下 main.go 文件,里面有几个帮助排除性能调问题的关键的的点,我加上了些注释方便你理解,如下:

package main

import (
	// 略
	_ "net/http/pprof" // 会自动注册 handler 到 http server,方便通过 http 接口获取程序运行采样报告
	// 略
)

func main() {
	// 略

	runtime.GOMAXPROCS(1) // 限制 CPU 使用数,避免过载
	runtime.SetMutexProfileFraction(1) // 开启对锁调用的跟踪
	runtime.SetBlockProfileRate(1) // 开启对阻塞操作的跟踪

	go func() {
		// 启动一个 http server,注意 pprof 相关的 handler 已经自动注册过了
		if err := http.ListenAndServe(":6060", nil); err != nil {
			log.Fatal(err)
		}
		os.Exit(0)
	}()

	// 略
}

除此之外的其他代码你一律不用看,那些都是我为了模拟一个“逻辑复杂”的程序而编造的,其中大多数的问题很容易通过肉眼发现,但我们需要做的是通过 pprof 来定位代码的问题,所以为了保证实验的趣味性请不要提前阅读代码,可以实验完成后再看。

接着我们需要编译一下这个程序并运行,你不用担心依赖问题,这个程序没有任何外部依赖。

go build
./go-pprof-practice

运行后注意查看一下资源是否吃紧,机器是否还能扛得住,坚持一分钟,如果确认没问题,咱们再进行下一步。

控制台里应该会不停的打印日志,都是一些“猫狗虎鼠在不停地吃喝拉撒”的屁话,没有意义,不用细看。

使用 pprof

保持程序运行,打开浏览器访问 http://localhost:6060/debug/pprof/,可以看到如下页面:

image.png

页面上展示了可用的程序运行采样数据,分别有:

类型 描述 备注
allocs 内存分配情况的采样信息 可以用浏览器打开,但可读性不高
blocks 阻塞操作情况的采样信息 可以用浏览器打开,但可读性不高
cmdline 显示程序启动命令及参数 可以用浏览器打开,这里会显示 ./go-pprof-practice
goroutine 当前所有协程的堆栈信息 可以用浏览器打开,但可读性不高
heap 堆上内存使用情况的采样信息 可以用浏览器打开,但可读性不高
mutex 锁争用情况的采样信息 可以用浏览器打开,但可读性不高
profile CPU 占用情况的采样信息 浏览器打开会下载文件
threadcreate 系统线程创建情况的采样信息 可以用浏览器打开,但可读性不高

因为 cmdline 没有什么实验价值,trace 与本文主题关系不大,threadcreate 涉及的情况偏复杂,所以这三个类型的采样信息这里暂且不提。除此之外,其他所有类型的采样信息本文都会涉及到,且炸弹程序已经为每一种类型的采样信息埋藏了一个对应的性能问题,等待你的发现。

由于直接阅读采样信息缺乏直观性,我们需要借助 go tool pprof 命令来排查问题,这个命令是 go 原生自带的,所以不用额外安装。

我们先不用完整地学习如何使用这个命令,毕竟那太枯燥了,我们一边实战一边学习。

以下正式开始。

排查 CPU 占用过高

我们首先通过活动监视器(或任务管理器、top 命令,取决于你的操作系统和你的喜好),查看一下炸弹程序的 CPU 占用:

image.png

可以看到 CPU 占用相当高,这显然是有问题的,我们使用 go tool pprof 来排场一下:

go tool pprof http://localhost:6060/debug/pprof/profile

等待一会儿后,进入一个交互式终端:

[root@master-20 ~]#go tool pprof http://localhost:6060/debug/pprof/profile
Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile
Saved profile in /root/pprof/pprof.go-pprof-practice.samples.cpu.001.pb.gz
File: go-pprof-practice
Type: cpu
Time: Apr 23, 2021 at 11:57am (CST)
Duration: 30.14s, Total samples = 19.66s (65.22%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)

 输入 top 命令,查看 CPU 占用较高的调用:

(pprof) top
Showing nodes accounting for 19.21s, 99.48% of 19.31s total
Dropped 22 nodes (cum <= 0.10s)
      flat  flat%   sum%        cum   cum%
    19.21s 99.48% 99.48%     19.26s 99.74%  go-pprof-practice/animal/felidae/tiger.(*Tiger).Eat
         0     0% 99.48%     19.26s 99.74%  go-pprof-practice/animal/felidae/tiger.(*Tiger).Live
         0     0% 99.48%     19.30s 99.95%  main.main
         0     0% 99.48%     19.30s 99.95%  runtime.main

很明显,CPU 占用过高是 go-pprof-practice/animal/felidae/tiger.(*Tiger).Eat 造成的。

注:为了保证实验节奏,关于图中 flatflat%sum%cumcum% 等参数的含义这里就不展开讲了,你可以先简单理解为数字越大占用情况越严重

输入 list Eat,查看问题具体在代码的哪一个位置:

(pprof) list Eat
Total: 19.31s
ROUTINE ======================== go-pprof-practice/animal/felidae/tiger.(*Tiger).Eat in /root/go-pprof-practice/animal/felidae/tiger/tiger.go
    19.21s     19.26s (flat, cum) 99.74% of Total
         .          .     19:}
         .          .     20:
         .          .     21:func (t *Tiger) Eat() {
         .          .     22:	log.Println(t.Name(), "eat")
         .          .     23:	loop := 10000000000
    19.21s     19.26s     24:	for i := 0; i < loop; i++ {
         .          .     25:		// do nothing
         .          .     26:	}
         .          .     27:}
         .          .     28:
         .          .     29:func (t *Tiger) Drink() {

可以看到,是第 24 行那个一百亿次空循环占用了大量 CPU 时间,至此,问题定位成功!

接下来有一个扩展操作:图形化显示调用栈信息,这很酷,但是需要你事先在机器上安装 graphviz,大多数系统上可以轻松安装它:

yum install graphviz

安装完成后,我们继续在上文的交互式终端里输入 web,注意,虽然这个命令的名字叫“web”,但它的实际行为是产生一个 .svg 文件,并调用你的系统里设置的默认打开 .svg 的程序打开它。如果你的系统里打开 .svg 的默认程序并不是浏览器(比如可能是你的代码编辑器),这时候你需要设置一下默认使用浏览器打开 .svg 文件,相信这难不倒你。

如果浏览器无法使用,可以输入 svg,然后会在当前目录生成svg文件,然后使用浏览器打开也可以看到

你应该可以看到:

image.png

图中,tiger.(*Tiger).Eat 函数的框特别大,箭头特别粗,pprof 生怕你不知道这个函数的 CPU 占用很高,这张图还包含了很多有趣且有价值的信息,你可以多看一会儿再继续。

至此,这一小节使用 pprof 定位 CPU 占用的实验就结束了,你需要输入 exit 退出 pprof 的交互式终端。

为了方便进行后面的实验,我们修复一下这个问题,不用太麻烦,注释掉相关代码即可:

func (t *Tiger) Eat() {
	log.Println(t.Name(), "eat")
	//loop := 10000000000
	//for i := 0; i < loop; i++ {
	//	// do nothing
	//}
}

之后修复问题的的方法都是注释掉相关的代码,不再赘述。你可能觉得这很粗暴,但要知道,这个实验的重点是如何使用 pprof 定位问题,我们不需要花太多时间在改代码上。

排查内存占用过高

重新编译炸弹程序,再次运行,可以看到 CPU 占用率已经下来了,但是内存的占用率仍然很高:

我们再次运行使用 pprof 命令,注意这次使用的 URL 的结尾是 heap:

go tool pprof http://localhost:6060/debug/pprof/heap

再次使用top,list来定位问题代码

[root@master-20 ~]#go tool pprof http://localhost:6060/debug/pprof/heap
Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap
Saved profile in /root/pprof/pprof.go-pprof-practice.alloc_objects.alloc_space.inuse_objects.inuse_space.001.pb.gz
File: go-pprof-practice
Type: inuse_space
Time: Apr 23, 2021 at 12:06pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 768MB, 100% of 768MB total
      flat  flat%   sum%        cum   cum%
     768MB   100%   100%      768MB   100%  go-pprof-practice/animal/muridae/mouse.(*Mouse).Steal
         0     0%   100%      768MB   100%  go-pprof-practice/animal/muridae/mouse.(*Mouse).Live
         0     0%   100%      768MB   100%  main.main
         0     0%   100%      768MB   100%  runtime.main
(pprof) list Steal
Total: 768MB
ROUTINE ======================== go-pprof-practice/animal/muridae/mouse.(*Mouse).Steal in /root/go-pprof-practice/animal/muridae/mouse/mouse.go
     768MB      768MB (flat, cum)   100% of Total
         .          .     45:
         .          .     46:func (m *Mouse) Steal() {
         .          .     47:	log.Println(m.Name(), "steal")
         .          .     48:	max := constant.Gi
         .          .     49:	for len(m.buffer) * constant.Mi < max {
     768MB      768MB     50:		m.buffer = append(m.buffer, [constant.Mi]byte{})
         .          .     51:	}
         .          .     52:}

可以看到这次出问题的地方在 go-pprof-practice/animal/muridae/mouse.(*Mouse).Steal,函数内容如下:

func (m *Mouse) Steal() {
	log.Println(m.Name(), "steal")
	max := constant.Gi	for len(m.buffer) * constant.Mi < max {
		m.buffer = append(m.buffer, [constant.Mi]byte{})
	}
}

可以看到,这里有个循环会一直向 m.buffer 里追加长度为 1 MiB 的数组,直到总容量到达 1 GiB 为止,且一直不释放这些内存,这就难怪会有这么高的内存占用了。

使用 svg  来查看图形化展示,可以再次确认问题确实出在这里:

image.png

现在我们同样是注释掉相关代码来解决这个问题。

再次编译运行,查看内存占用,可以看到内存占用已经将到了 35 MB,似乎内存的使用已经恢复正常,一片祥和。

但是,内存相关的性能问题真的已经全部解决了吗?

排查频繁内存回收

你应该知道,频繁的 GC 对 golang 程序性能的影响也是非常严重的。虽然现在这个炸弹程序内存使用量并不高,但这会不会是频繁 GC 之后的假象呢?

为了获取程序运行过程中 GC 日志,我们需要先退出炸弹程序,再在重新启动前赋予一个环境变量,同时为了避免其他日志的干扰,使用 grep 筛选出 GC 日志查看:

GODEBUG=gctrace=1 ./go-pprof-practice | grep gc

日志输出如下:

[root@master-20 ~/go-pprof-practice]#GODEBUG=gctrace=1 ./go-pprof-practice | grep gc
gc 1 @0.001s 4%: 0.002+0.25+0.001 ms clock, 0.002+0.12/0.056/0+0.001 ms cpu, 16->16->0 MB, 17 MB goal, 1 P
gc 2 @3.008s 0%: 0.008+0.56+0.003 ms clock, 0.008+0.25/0.15/0+0.003 ms cpu, 16->16->0 MB, 17 MB goal, 1 P
gc 3 @6.011s 0%: 0.003+0.29+0.001 ms clock, 0.003+0.12/0.087/0+0.001 ms cpu, 16->16->0 MB, 17 MB goal, 1 P
gc 4 @9.016s 0%: 0.006+0.48+0.003 ms clock, 0.006+0.19/0.16/0+0.003 ms cpu, 16->16->0 MB, 17 MB goal, 1 P

可以看到,GC 差不多每 3 秒就发生一次,且每次 GC 都会从 16MB 清理到几乎 0MB,说明程序在不断的申请内存再释放,这是高性能 golang 程序所不允许的。

所以接下来使用 pprof 排查时,我们在乎的不是什么地方在占用大量内存,而是什么地方在不停地申请内存,这两者是有区别的。

由于内存的申请与释放频度是需要一段时间来统计的,所有我们保证炸弹程序已经运行了几分钟之后,再运行命令:

go tool pprof http://localhost:6060/debug/pprof/allocs

同样使用 top、list、svg大法:

[root@master-20 ~]#go tool pprof http://localhost:6060/debug/pprof/allocs
Fetching profile over HTTP from http://localhost:6060/debug/pprof/allocs
Saved profile in /root/pprof/pprof.go-pprof-practice.alloc_objects.alloc_space.inuse_objects.inuse_space.002.pb.gz
File: go-pprof-practice
Type: alloc_space
Time: Apr 23, 2021 at 12:11pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 32MB, 100% of 32MB total
      flat  flat%   sum%        cum   cum%
      32MB   100%   100%       32MB   100%  go-pprof-practice/animal/canidae/dog.(*Dog).Run (inline)
         0     0%   100%       32MB   100%  go-pprof-practice/animal/canidae/dog.(*Dog).Live
         0     0%   100%       32MB   100%  main.main
         0     0%   100%       32MB   100%  runtime.main
(pprof) list Run
Total: 32MB
ROUTINE ======================== go-pprof-practice/animal/canidae/dog.(*Dog).Run in /root/go-pprof-practice/animal/canidae/dog/dog.go
      32MB       32MB (flat, cum)   100% of Total
         .          .     38:	log.Println(d.Name(), "pee")
         .          .     39:}
         .          .     40:
         .          .     41:func (d *Dog) Run() {
         .          .     42:	log.Println(d.Name(), "run")
      32MB       32MB     43:	_ = make([]byte, 16 * constant.Mi)
         .          .     44:}
         .          .     45:
         .          .     46:func (d *Dog) Howl() {
         .          .     47:	log.Println(d.Name(), "howl")
         .          .     48:}

可以看到 go-pprof-practice/animal/canidae/dog.(*Dog).Run 会进行无意义的内存申请,而这个函数又会被频繁调用,这才导致程序不停地进行 GC:

func (d *Dog) Run() {
	log.Println(d.Name(), "run")
	_ = make([]byte, 16 * constant.Mi)
}

这里有个小插曲,你可尝试一下将 16 * constant.Mi 修改成一个较小的值,重新编译运行,会发现并不会引起频繁 GC,原因是在 golang 里,对象是使用堆内存还是栈内存,由编译器进行逃逸分析并决定,如果对象不会逃逸,便可在使用栈内存,但总有意外,就是对象的尺寸过大时,便不得不使用堆内存。所以这里设置申请 16 MiB 的内存就是为了避免编译器直接在栈上分配,如果那样得话就不会涉及到 GC 了。

我们同样注释掉问题代码,重新编译执行,可以看到这一次,程序的 GC 频度要低很多,以至于短时间内都看不到 GC 日志了:

排查协程泄露

由于 golang 自带内存回收,所以一般不会发生内存泄露。但凡事都有例外,在 golang 中,协程本身是可能泄露的,或者叫协程失控,进而导致内存泄露。

虽然 106 条并不算多,但对于这样一个小程序来说,似乎还是不正常的。为求安心,我们再次是用 pprof 来排查一下:

go tool pprof http://localhost:6060/debug/pprof/goroutine

同样是 top、list、svg大法:

[root@master-20 ~]#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.go-pprof-practice.goroutine.001.pb.gz
File: go-pprof-practice
Type: goroutine
Time: Apr 23, 2021 at 12:14pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 105, 100% of 105 total
Showing top 10 nodes out of 35
      flat  flat%   sum%        cum   cum%
       103 98.10% 98.10%        103 98.10%  runtime.gopark
         1  0.95% 99.05%          1  0.95%  net/http.(*connReader).backgroundRead
         1  0.95%   100%          1  0.95%  runtime/pprof.writeRuntimeProfile
         0     0%   100%        100 95.24%  go-pprof-practice/animal/canidae/wolf.(*Wolf).Drink.func1
         0     0%   100%          1  0.95%  go-pprof-practice/animal/canidae/wolf.(*Wolf).Howl
         0     0%   100%          1  0.95%  go-pprof-practice/animal/canidae/wolf.(*Wolf).Howl.func1
         0     0%   100%          1  0.95%  go-pprof-practice/animal/canidae/wolf.(*Wolf).Live
         0     0%   100%          1  0.95%  internal/poll.(*FD).Accept
         0     0%   100%          1  0.95%  internal/poll.(*pollDesc).wait
         0     0%   100%          1  0.95%  internal/poll.(*pollDesc).waitRead (inline)
(pprof) list Drink
Total: 105
ROUTINE ======================== go-pprof-practice/animal/canidae/wolf.(*Wolf).Drink.func1 in /root/go-pprof-practice/animal/canidae/wolf/wolf.go
         0        100 (flat, cum) 95.24% of Total
         .          .     29:
         .          .     30:func (w *Wolf) Drink() {
         .          .     31:	log.Println(w.Name(), "drink")
         .          .     32:	for i := 0; i < 10; i++ {
         .          .     33:		go func() {
         .        100     34:			time.Sleep(30 * time.Second)
         .          .     35:		}()
         .          .     36:	}
         .          .     37:}
         .          .     38:
         .          .     39:func (w *Wolf) Shit() {

image.png

可能这次问题藏得比较隐晦,但仔细观察还是不难发现,问题在于 go-pprof-practice/animal/canidae/wolf.(*Wolf).Drink 在不停地创建没有实际作用的协程:

func (w *Wolf) Drink() {
	log.Println(w.Name(), "drink")
	for i := 0; i < 10; i++ {
		go func() {
			time.Sleep(30 * time.Second)
		}()
	}
}

可以看到,Drink 函数每次回释放 10 个协程出去,每个协程会睡眠 30 秒再退出,而 Drink 函数又会被反复调用,这才导致大量协程泄露,试想一下,如果释放出的协程会永久阻塞,那么泄露的协程数便会持续增加,内存的占用也会持续增加,那迟早是会被操作系统杀死的。

我们注释掉问题代码,重新编译运行可以看到,协程数已经降到 4 条了

排查锁的争用

到目前为止,我们已经解决这个炸弹程序的所有资源占用问题,但是事情还没有完,我们需要进一步排查那些会导致程序运行慢的性能问题,这些问题可能并不会导致资源占用,但会让程序效率低下,这同样是高性能程序所忌讳的。

我们首先想到的就是程序中是否有不合理的锁的争用,我们倒一倒,回头看看上一张图,虽然协程数已经降到 4 条,但还显示有一个 mutex 存在争用问题。

相信到这里,你已经触类旁通了,无需多言,开整。

go tool pprof http://localhost:6060/debug/pprof/mutex

同样是 top、list、svg大法:

[root@master-20 ~]#go tool pprof http://localhost:6060/debug/pprof/mutex
Fetching profile over HTTP from http://localhost:6060/debug/pprof/mutex
Saved profile in /root/pprof/pprof.go-pprof-practice.contentions.delay.001.pb.gz
File: go-pprof-practice
Type: delay
Time: Apr 23, 2021 at 12:18pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 2.12mins, 100% of 2.12mins total
      flat  flat%   sum%        cum   cum%
  2.12mins   100%   100%   2.12mins   100%  sync.(*Mutex).Unlock (inline)
         0     0%   100%   2.12mins   100%  go-pprof-practice/animal/canidae/wolf.(*Wolf).Howl.func1
(pprof) list wolf
Total: 2.12mins
ROUTINE ======================== go-pprof-practice/animal/canidae/wolf.(*Wolf).Howl.func1 in /root/go-pprof-practice/animal/canidae/wolf/wolf.go
         0   2.12mins (flat, cum)   100% of Total
         .          .     53:
         .          .     54:	m := &sync.Mutex{}
         .          .     55:	m.Lock()
         .          .     56:	go func() {
         .          .     57:		time.Sleep(time.Second)
         .   2.12mins     58:		m.Unlock()
         .          .     59:	}()
         .          .     60:	m.Lock()
         .          .     61:}

可以看出来这问题出在 go-pprof-practice/animal/canidae/wolf.(*Wolf).Howl。但要知道,在代码中使用锁是无可非议的,并不是所有的锁都会被标记有问题,我们看看这个有问题的锁那儿触雷了。

func (w *Wolf) Howl() {
	log.Println(w.Name(), "howl")

	m := &sync.Mutex{}
	m.Lock()	go func() {
		time.Sleep(time.Second)
		m.Unlock()
	}()
	m.Lock()
}

可以看到,这个锁由主协程 Lock,并启动子协程去 Unlock,主协程会阻塞在第二次 Lock 这儿等待子协程完成任务,但由于子协程足足睡眠了一秒,导致主协程等待这个锁释放足足等了一秒钟。虽然这可能是实际的业务需要,逻辑上说得通,并不一定真的是性能瓶颈,但既然它出现在我写的“炸弹”里,就肯定不是什么“业务需要”啦。

所以,我们注释掉这段问题代码,重新编译执行,继续。

排查阻塞操作

好了,我们开始排查最后一个问题。

在程序中,除了锁的争用会导致阻塞之外,很多逻辑都会导致阻塞。

可以看到,这里仍有 2 个阻塞操作,虽然不一定是有问题的,但我们保证程序性能,我们还是要老老实实排查确认一下才对。

go tool pprof http://localhost:6060/debug/pprof/block

top、list、svg,你懂得。

(pprof) top
Showing nodes accounting for 5.55mins, 100% of 5.55mins total
Dropped 4 nodes (cum <= 0.03mins)
      flat  flat%   sum%        cum   cum%
  2.79mins 50.15% 50.15%   2.79mins 50.15%  sync.(*Mutex).Lock (inline)
  2.77mins 49.85%   100%   2.77mins 49.85%  runtime.chanrecv1
         0     0%   100%   2.79mins 50.15%  go-pprof-practice/animal/canidae/wolf.(*Wolf).Howl
         0     0%   100%   2.79mins 50.15%  go-pprof-practice/animal/canidae/wolf.(*Wolf).Live
         0     0%   100%   2.77mins 49.85%  go-pprof-practice/animal/felidae/cat.(*Cat).Live
         0     0%   100%   2.77mins 49.85%  go-pprof-practice/animal/felidae/cat.(*Cat).Pee
         0     0%   100%   5.55mins   100%  main.main
         0     0%   100%   5.55mins   100%  runtime.main
(pprof) list Pee
Total: 5.55mins
ROUTINE ======================== go-pprof-practice/animal/felidae/cat.(*Cat).Pee in /root/go-pprof-practice/animal/felidae/cat/cat.go
         0   2.77mins (flat, cum) 49.85% of Total
         .          .     34:}
         .          .     35:
         .          .     36:func (c *Cat) Pee() {
         .          .     37:	log.Println(c.Name(), "pee")
         .          .     38:
         .   2.77mins     39:	<-time.After(time.Second)
         .          .     40:}
         .          .     41:
         .          .     42:func (c *Cat) Climb() {
         .          .     43:	log.Println(c.Name(), "climb")
         .          .     44:}

未经允许不得转载:江哥架构师笔记 » go学习:pprof基础使用

分享到:更多 ()

评论 抢沙发

评论前必须登录!