本篇介绍 Golang 常用性能调试工具的应用场景,包括:
场景 1 如何分析程序的运行时间与 CPU 利用率情况?
场景 2 如何分析 Golang 程序的内存使用情况?
场景 3 如何分析 Golang 程序的 CPU 性能情况?
场景 1: 如何分析程序的运行时间与 CPU 利用率情况?
(1) shell 内置 time 指令
这个方法不算新颖,但是确很实用。 time
是 Unix/Linux 内置多命令,使用时一般不用传过多参数,直接跟上需要调试多程序即可。
$ time go run test2.go
&{{0 0} 张三 0}
real 0m0.843s
user 0m0.216s
sys 0m0.389s
上面是使用 time 对 go run test2.go
对执行程序坐了性能分析,得到 3 个指标。
-
real
:从程序开始到结束,实际度过的时间; -
user
:程序在用户态度过的时间; -
sys
:程序在内核态度过的时间。
一般情况下 real
>= user
+ sys
,因为系统还有其它进程 (切换其他进程中间对于本进程回有空白期)。
(2) /usr/bin/time 指令
这个指令比内置的 time 更加详细一些,使用的时候需要用绝对路径,而且要加上参数-v
$ /usr/bin/time -v go run test2.go
Command being timed: "go run test2.go"
User time (seconds): 0.12
System time (seconds): 0.06
Percent of CPU this job got: 115%
Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.16
Average shared text size (kbytes): 0
Average unshared data size (kbytes): 0
Average stack size (kbytes): 0
Average total size (kbytes): 0
Maximum resident set size (kbytes): 41172
Average resident set size (kbytes): 0
Major (requiring I/O) page faults: 1
Minor (reclaiming a frame) page faults: 15880
Voluntary context switches: 897
Involuntary context switches: 183
Swaps: 0
File system inputs: 256
File system outputs: 2664
Socket messages sent: 0
Socket messages received: 0
Signals delivered: 0
Page size (bytes): 4096
Exit status: 0
可以看到这里的功能要强大多了,除了之前的信息外,还包括了:
- CPU 占用率;
- 内存使用情况;
- Page Fault 情况;
- 进程切换情况;
- 文件系统 IO;
- Socket 使用情况;
- ……
场景 2: 如何分析 golang 程序的内存使用情况?
(1) 内存占用情况查看
我们先写一段 demo 例子代码
package main
import (
"log"
"runtime"
"time"
)
func test() {
//slice 会动态扩容,用slice来做堆内存申请
container := make([]int, 8)
log.Println(" ===> loop begin.")
for i := 0; i < 32*1000*1000; i++ {
container = append(container, i)
}
log.Println(" ===> loop end.")
}
func main() {
log.Println("Start.")
test()
log.Println("force gc.")
runtime.GC() //强制调用gc回收
log.Println("Done.")
time.Sleep(3600 * time.Second) //睡眠,保持程序不退出
}
编译
$go build -o snippet_mem && ./snippet_mem
然后在./snippet_mem 进程没有执行完,我们再开一个窗口,通过top
命令查看进程的内存占用情况
$top -p $(pidof snippet_mem)
得到结果如下:
我们看出来,没有退出的 snippet_mem 进程有约 830m 的内存被占用。
直观上来说,这个程序在test()
函数执行完后,切片contaner
的内存应该被释放,不应该占用 830M 那么大。
下面让我们使用 GODEBUG 来分析程序的内存使用情况。
(2) GODEBUG 与 gctrace
用法
执行snippet_mem
程序之前添加环境变量GODEBUG='gctrace=1'
来跟踪打印垃圾回收器信息
$ GODEBUG='gctrace=1' ./snippet_mem
设置gctrace=1
会使得垃圾回收器在每次回收时汇总所回收内存的大小以及耗时, 并将这些内容汇总成单行内容打印到标准错误输出中。
格式
gc # @#s #%: #+#+# ms clock, #+#/#/#+# ms cpu, #->#-># MB, # MB goal, # P
含义
gc # GC次数的编号,每次GC时递增
@#s 距离程序开始执行时的时间
#% GC占用的执行时间百分比
#+...+# GC使用的时间
#->#-># MB GC开始,结束,以及当前活跃堆内存的大小,单位M
# MB goal 全局堆内存大小
# P 使用processor的数量
如果每条信息最后,以(forced)
结尾,那么该信息是由runtime.GC()
调用触发
我们来选择其中一行来解释一下:
gc 17 @0.149s 1%: 0.004+36+0.003 ms clock, 0.009+0/0.051/36+0.006 ms cpu, 181->181->101 MB, 182 MB goal, 2 P
该条信息含义如下:
-
gc 17
: Gc 调试编号为 17 -
@0.149s
:此时程序已经执行了 0.149s -
1%
: 0.149s 中其中 gc 模块占用了 1% 的时间 -
0.004+36+0.003 ms clock
: 垃圾回收的时间,分别为 STW(stop-the-world)清扫的时间 + 并发标记和扫描的时间 +STW 标记的时间 -
0.009+0/0.051/36+0.006 ms cpu
: 垃圾回收占用 cpu 时间 -
181->181->101 MB
: GC 开始前堆内存 181M, GC 结束后堆内存 181M,当前活跃的堆内存 101M -
182 MB goal
: 全局堆内存大小 -
2 P
: 本次 GC 使用了 2 个 P(调度器中的 Processer)
了解了 GC 的调试信息读法后,接下来我们来分析一下本次 GC 的结果。
我们还是执行 GODEBUG 调试
$ GODEBUG='gctrace=1' ./snippet_mem
结果如下
2020/03/02 11:22:37 Start.
2020/03/02 11:22:37 ===> loop begin.
gc 1 @0.002s 5%: 0.14+0.45+0.002 ms clock, 0.29+0/0.042/0.33+0.005 ms cpu, 4->4->0 MB, 5 MB goal, 2 P
gc 2 @0.003s 4%: 0.13+3.7+0.019 ms clock, 0.27+0/0.037/2.8+0.038 ms cpu, 4->4->2 MB, 5 MB goal, 2 P
gc 3 @0.008s 3%: 0.002+1.1+0.001 ms clock, 0.005+0/0.083/1.0+0.003 ms cpu, 6->6->2 MB, 7 MB goal, 2 P
gc 4 @0.010s 3%: 0.003+0.99+0.002 ms clock, 0.006+0/0.041/0.82+0.004 ms cpu, 5->5->2 MB, 6 MB goal, 2 P
gc 5 @0.011s 4%: 0.079+0.80+0.003 ms clock, 0.15+0/0.046/0.51+0.006 ms cpu, 6->6->3 MB, 7 MB goal, 2 P
gc 6 @0.013s 4%: 0.15+3.7+0.002 ms clock, 0.31+0/0.061/3.3+0.005 ms cpu, 8->8->8 MB, 9 MB goal, 2 P
gc 7 @0.019s 3%: 0.004+2.5+0.005 ms clock, 0.008+0/0.051/2.1+0.010 ms cpu, 20->20->6 MB, 21 MB goal, 2 P
gc 8 @0.023s 5%: 0.014+3.7+0.002 ms clock, 0.029+0.040/1.2/0+0.005 ms cpu, 15->15->8 MB, 16 MB goal, 2 P
gc 9 @0.031s 4%: 0.003+1.6+0.001 ms clock, 0.007+0.094/0/0+0.003 ms cpu, 19->19->10 MB, 20 MB goal, 2 P
gc 10 @0.034s 3%: 0.006+5.2+0.004 ms clock, 0.013+0/0.045/5.0+0.008 ms cpu, 24->24->13 MB, 25 MB goal, 2 P
gc 11 @0.040s 3%: 0.12+2.6+0.002 ms clock, 0.24+0/0.043/2.5+0.004 ms cpu, 30->30->16 MB, 31 MB goal, 2 P
gc 12 @0.043s 3%: 0.11+4.4+0.002 ms clock, 0.23+0/0.044/4.1+0.005 ms cpu, 38->38->21 MB, 39 MB goal, 2 P
gc 13 @0.049s 3%: 0.008+10+0.040 ms clock, 0.017+0/0.045/10+0.080 ms cpu, 47->47->47 MB, 48 MB goal, 2 P
gc 14 @0.070s 2%: 0.004+12+0.002 ms clock, 0.008+0/0.062/12+0.005 ms cpu, 122->122->41 MB, 123 MB goal, 2 P
gc 15 @0.084s 2%: 0.11+11+0.038 ms clock, 0.22+0/0.064/3.9+0.076 ms cpu, 93->93->93 MB, 94 MB goal, 2 P
gc 16 @0.122s 1%: 0.005+25+0.010 ms clock, 0.011+0/0.12/24+0.021 ms cpu, 238->238->80 MB, 239 MB goal, 2 P
gc 17 @0.149s 1%: 0.004+36+0.003 ms clock, 0.009+0/0.051/36+0.006 ms cpu, 181->181->101 MB, 182 MB goal, 2 P
gc 18 @0.187s 1%: 0.12+19+0.004 ms clock, 0.25+0/0.049/19+0.008 ms cpu, 227->227->126 MB, 228 MB goal, 2 P
gc 19 @0.207s 1%: 0.096+27+0.004 ms clock, 0.19+0/0.077/0.73+0.009 ms cpu, 284->284->284 MB, 285 MB goal, 2 P
gc 20 @0.287s 0%: 0.005+944+0.040 ms clock, 0.011+0/0.048/1.3+0.081 ms cpu, 728->728->444 MB, 729 MB goal, 2 P
2020/03/02 11:22:38 ===> loop end.
2020/03/02 11:22:38 force gc.
gc 21 @1.236s 0%: 0.004+0.099+0.001 ms clock, 0.008+0/0.018/0.071+0.003 ms cpu, 444->444->0 MB, 888 MB goal, 2 P (forced)
2020/03/02 11:22:38 Done.
GC forced
gc 22 @122.455s 0%: 0.010+0.15+0.003 ms clock, 0.021+0/0.025/0.093+0.007 ms cpu, 0->0->0 MB, 4 MB goal, 2 P
GC forced
gc 23 @242.543s 0%: 0.007+0.075+0.002 ms clock, 0.014+0/0.022/0.085+0.004 ms cpu, 0->0->0 MB, 4 MB goal, 2 P
GC forced
gc 24 @362.545s 0%: 0.018+0.19+0.006 ms clock, 0.037+0/0.055/0.15+0.013 ms cpu, 0->0->0 MB, 4 MB goal, 2 P
GC forced
gc 25 @482.548s 0%: 0.012+0.25+0.005 ms clock, 0.025+0/0.025/0.11+0.010 ms cpu, 0->0->0 MB, 4 MB goal, 2 P
GC forced
gc 26 @602.551s 0%: 0.009+0.10+0.003 ms clock, 0.018+0/0.021/0.075+0.006 ms cpu, 0->0->0 MB, 4 MB goal, 2 P
GC forced
gc 27 @722.554s 0%: 0.012+0.30+0.005 ms clock, 0.025+0/0.15/0.22+0.011 ms cpu, 0->0->0 MB, 4 MB goal, 2 P
GC forced
gc 28 @842.556s 0%: 0.027+0.18+0.003 ms clock, 0.054+0/0.11/0.14+0.006 ms cpu, 0->0->0 MB, 4 MB goal, 2 P
...
分析
先看在test()
函数执行完后立即打印的gc 21
那行的信息。444->444->0 MB, 888 MB goal
表示垃圾回收器已经把 444M 的内存标记为非活跃的内存。
再看下一个记录gc 22
。0->0->0 MB, 4 MB goal
表示垃圾回收器中的全局堆内存大小由888M
下降为4M
。
结论
1、在 test() 函数执行完后,demo 程序中的切片容器所申请的堆空间都被垃圾回收器回收了。
2、如果此时在top
指令查询内存的时候,如果依然先死 800+MB,说明垃圾回收器回收了应用层的内存后,(可能)并不会立即将内存归还给系统。
(3) runtime.ReadMemStats
接下来我么换另一种方式查看内存的方式 利用 runtime 库里的ReadMemStats()
方法
demo2.go
package main
import (
"log"
"runtime"
"time"
)
func readMemStats() {
var ms runtime.MemStats
runtime.ReadMemStats(&ms)
log.Printf(" ===> Alloc:%d(bytes) HeapIdle:%d(bytes) HeapReleased:%d(bytes)", ms.Alloc, ms.HeapIdle, ms.HeapReleased)
}
func test() {
//slice 会动态扩容,用slice来做堆内存申请
container := make([]int, 8)
log.Println(" ===> loop begin.")
for i := 0; i < 32*1000*1000; i++ {
container = append(container, i)
if ( i == 16*1000*1000) {
readMemStats()
}
}
log.Println(" ===> loop end.")
}
func main() {
log.Println(" ===> [Start].")
readMemStats()
test()
readMemStats()
log.Println(" ===> [force gc].")
runtime.GC() //强制调用gc回收
log.Println(" ===> [Done].")
readMemStats()
go func() {
for {
readMemStats()
time.Sleep(10 * time.Second)
}
}()
time.Sleep(3600 * time.Second) //睡眠,保持程序不退出
}
这里我们, 封装了一个函数readMemStats()
,这里面主要是调用runtime
中的ReadMemStats()
方法获得内存信息,然后通过log
打印出来。
我们执行一下代码并运行
$ go run demo2.go
2020/03/02 18:21:17 ===> [Start].
2020/03/02 18:21:17 ===> Alloc:71280(bytes) HeapIdle:66633728(bytes) HeapReleased:66600960(bytes)
2020/03/02 18:21:17 ===> loop begin.
2020/03/02 18:21:18 ===> Alloc:132535744(bytes) HeapIdle:336756736(bytes) HeapReleased:155721728(bytes)
2020/03/02 18:21:38 ===> loop end.
2020/03/02 18:21:38 ===> Alloc:598300600(bytes) HeapIdle:609181696(bytes) HeapReleased:434323456(bytes)
2020/03/02 18:21:38 ===> [force gc].
2020/03/02 18:21:38 ===> [Done].
2020/03/02 18:21:38 ===> Alloc:55840(bytes) HeapIdle:1207427072(bytes) HeapReleased:434266112(bytes)
2020/03/02 18:21:38 ===> Alloc:56656(bytes) HeapIdle:1207394304(bytes) HeapReleased:434266112(bytes)
2020/03/02 18:21:48 ===> Alloc:56912(bytes) HeapIdle:1207394304(bytes) HeapReleased:1206493184(bytes)
2020/03/02 18:21:58 ===> Alloc:57488(bytes) HeapIdle:1207394304(bytes) HeapReleased:1206493184(bytes)
2020/03/02 18:22:08 ===> Alloc:57616(bytes) HeapIdle:1207394304(bytes) HeapReleased:1206493184(bytes)
c2020/03/02 18:22:18 ===> Alloc:57744(bytes) HeapIdle:1207394304(bytes) HeapReleased:1206493184(by
可以看到,打印[Done].
之后那条 trace 信息,Alloc 已经下降,即内存已被垃圾回收器回收。在2020/03/02 18:21:38
和2020/03/02 18:21:48
的两条 trace 信息中,HeapReleased 开始上升,即垃圾回收器把内存归还给系统。
另外,MemStats 还可以获取其它哪些信息以及字段的含义可以参见官方文档:
(4) pprof 工具
pprof 工具支持网页上查看内存的使用情况,需要在代码中添加一个协程即可。
import(
"net/http"
_ "net/http/pprof"
)
go func() {
log.Println(http.ListenAndServe("0.0.0.0:10000", nil))
}()
具体添加的完整代码如下:
demo3.go
package main
import (
"log"
"runtime"
"time"
"net/http"
_ "net/http/pprof"
)
func readMemStats() {
var ms runtime.MemStats
runtime.ReadMemStats(&ms)
log.Printf(" ===> Alloc:%d(bytes) HeapIdle:%d(bytes) HeapReleased:%d(bytes)", ms.Alloc, ms.HeapIdle, ms.HeapReleased)
}
func test() {
//slice 会动态扩容,用slice来做堆内存申请
container := make([]int, 8)
log.Println(" ===> loop begin.")
for i := 0; i < 32*1000*1000; i++ {
container = append(container, i)
if ( i == 16*1000*1000) {
readMemStats()
}
}
log.Println(" ===> loop end.")
}
func main() {
//启动pprof
go func() {
log.Println(http.ListenAndServe("0.0.0.0:10000", nil))
}()
log.Println(" ===> [Start].")
readMemStats()
test()
readMemStats()
log.Println(" ===> [force gc].")
runtime.GC() //强制调用gc回收
log.Println(" ===> [Done].")
readMemStats()
go func() {
for {
readMemStats()
time.Sleep(10 * time.Second)
}
}()
time.Sleep(3600 * time.Second) //睡眠,保持程序不退出
}
我们正常运行程序,然后同时打开浏览器,
输入地址:http://127.0.0.1:10000/debug/pprof/heap?debug=1
浏览器的内容其中有一部分如下,记录了目前的内存情况
# ...
# runtime.MemStats
# Alloc = 228248
# TotalAlloc = 1293696976
# Sys = 834967896
# Lookups = 0
# Mallocs = 2018
# Frees = 671
# HeapAlloc = 228248
# HeapSys = 804913152
# HeapIdle = 804102144
# HeapInuse = 811008
# HeapReleased = 108552192
# HeapObjects = 1347
# Stack = 360448 / 360448
# MSpan = 28288 / 32768
# MCache = 3472 / 16384
# BuckHashSys = 1449617
# GCSys = 27418976
# OtherSys = 776551
# NextGC = 4194304
# LastGC = 1583203571137891390
# ...
场景 3: 如何分析 Golang 程序的 CPU 性能情况?
(1) 性能分析注意事项
- 性能分析必须在一个
可重复的、稳定的环境中来进行。
- 机器必须闲置
- 不要在共享硬件上进行性能分析;
- 不要在性能分析期间,在同一个机器上去浏览网页
- 注意省电模式和过热保护,如果突然进入这些模式,会导致分析数据严重不准确
- 不要使用虚拟机、共享的云主机,太多干扰因素,分析数据会很不一致;
- 不要在 macOS 10.11 及以前的版本运行性能分析,有 bug,之后的版本修复了。
如果承受得起,购买专用的性能测试分析的硬件设备,上架。
- 关闭电源管理、过热管理;
- 绝不要升级,以保证测试的一致性,以及具有可比性。
如果没有这样的环境,那就一定要在多个环境中,执行多次,以取得可参考的、具有相对一致性的测试结果。
(2) CPU 性能分析
我们来用下面的代码进行测试
demo4.go
package main
import (
"bytes"
"math/rand"
"time"
"log"
"net/http"
_ "net/http/pprof"
)
func test() {
log.Println(" ===> loop begin.")
for i := 0; i < 1000; i++ {
log.Println(genSomeBytes())
}
log.Println(" ===> loop end.")
}
//生成一个随机字符串
func genSomeBytes() *bytes.Buffer {
var buff bytes.Buffer
for i := 1; i < 20000; i++ {
buff.Write([]byte{'0' + byte(rand.Intn(10))})
}
return &buff
}
func main() {
go func() {
for {
test()
time.Sleep(time.Second * 1)
}
}()
//启动pprof
http.ListenAndServe("0.0.0.0:10000", nil)
}
这里面还是启动了 pprof 的坚挺,有关pprof
启动的代码如下
import (
"net/http"
_ "net/http/pprof"
)
func main() {
//...
//...
//启动pprof
http.ListenAndServe("0.0.0.0:10000", nil)
}
main()
里的流程很简单,启动一个 goroutine 去无限循环调用test()
方法,休眠 1s.
test()
的流程是生成 1000 个 20000 个字符的随机字符串.并且打印.
我们将上面的代码编译成可执行的二进制文件 demo4
(记住这个名字,稍后我们能用到)
$ go build demo4.go
接下来我们启动程序,程序会无限循环的打印字符串.
接下来我们通过几种方式来查看进程的 cpu 性能情况.
A. Web 界面查看
浏览器访问http://127.0.0.1:10000/debug/pprof/
我们会看到如下画面
这里面能够通过 pprof 查看包括 (阻塞信息、cpu 信息、内存堆信息、锁信息、goroutine 信息等等), 我们这里关心的 cpu 的性能的profile
信息.
有关profile
下面的英文解释大致如下:
“CPU 配置文件。您可以在秒 GET 参数中指定持续时间。获取概要文件后,请使用 go tool pprof 命令调查概要文件。”
所以我们要是想得到 cpu 性能,就是要获取到当前进程的profile
文件,这个文件默认是 30s 生成一个,所以你的程序要至少运行 30s 以上 (这个参数也可以修改,稍后我们介绍)
我们可以直接点击网页的profile
,浏览器会给我们下载一个profile
文件. 记住这个文件的路径, 可以拷贝到与demo4
所在的同一文件夹下.
B. 使用 pprof 工具查看
pprof 的格式如下
go tool pprof [binary] [profile]
binary: 必须指向生成这个性能分析数据的那个二进制可执行文件;
profile: 必须是该二进制可执行文件所生成的性能分析数据文件。
binary
和 profile
必须严格匹配。
我们来查看一下:
$ go tool pprof ./demo4 profile
File: demo4
Type: cpu
Time: Mar 3, 2020 at 11:18pm (CST)
Duration: 30.13s, Total samples = 6.27s (20.81%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)
help可以查看一些指令,我么可以通过top来查看 cpu 的性能情况.
(pprof) top
Showing nodes accounting for 5090ms, 81.18% of 6270ms total
Dropped 80 nodes (cum <= 31.35ms)
Showing top 10 nodes out of 60
flat flat% sum% cum cum%
1060ms 16.91% 16.91% 2170ms 34.61% math/rand.(*lockedSource).Int63
850ms 13.56% 30.46% 850ms 13.56% sync.(*Mutex).Unlock (inline)
710ms 11.32% 41.79% 2950ms 47.05% math/rand.(*Rand).Int31n
570ms 9.09% 50.88% 990ms 15.79% bytes.(*Buffer).Write
530ms 8.45% 59.33% 540ms 8.61% syscall.Syscall
370ms 5.90% 65.23% 370ms 5.90% runtime.procyield
270ms 4.31% 69.54% 4490ms 71.61% main.genSomeBytes
250ms 3.99% 73.52% 3200ms 51.04% math/rand.(*Rand).Intn
250ms 3.99% 77.51% 250ms 3.99% runtime.memmove
230ms 3.67% 81.18% 690ms 11.00% runtime.suspendG
(pprof)
这里面有几列数据,需要说明一下.
- flat:当前函数占用 CPU 的耗时
- flat::当前函数占用 CPU 的耗时百分比
- sun%:函数占用 CPU 的耗时累计百分比
- cum:当前函数加上调用当前函数的函数占用 CPU 的总耗时
- cum%:当前函数加上调用当前函数的函数占用 CPU 的总耗时百分比
- 最后一列:函数名称
通过结果我们可以看出, 该程序的大部分 cpu 性能消耗在 main.getSoneBytes()
方法中,其中 math/rand 取随机数消耗比较大.
C. 通过 go tool pprof 得到 profile 文件
我们上面的 profile 文件是通过 web 浏览器下载的,这个 profile 的经过时间是 30s 的,默认值我们在浏览器上修改不了,如果你想得到时间更长的 cpu 利用率,可以通过go tool pprof
指令与程序交互来获取到
首先,我们先启动程序
$ ./demo4
然后再打开一个终端
go tool pprof http://localhost:10000/debug/pprof/profile?seconds=60
这里制定了生成 profile 文件的时间间隔 60s
等待 60s 之后, 终端就会有结果出来,我们继续使用 top 来查看.
$ go tool pprof http://localhost:10000/debug/pprof/profile?seconds=60
Fetching profile over HTTP from http://localhost:10000/debug/pprof/profile?seconds=60
Saved profile in /home/itheima/pprof/pprof.demo4.samples.cpu.005.pb.gz
File: demo4
Type: cpu
Time: Mar 3, 2020 at 11:59pm (CST)
Duration: 1mins, Total samples = 12.13s (20.22%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 9940ms, 81.95% of 12130ms total
Dropped 110 nodes (cum <= 60.65ms)
Showing top 10 nodes out of 56
flat flat% sum% cum cum%
2350ms 19.37% 19.37% 4690ms 38.66% math/rand.(*lockedSource).Int63
1770ms 14.59% 33.97% 1770ms 14.59% sync.(*Mutex).Unlock (inline)
1290ms 10.63% 44.60% 6040ms 49.79% math/rand.(*Rand).Int31n
1110ms 9.15% 53.75% 1130ms 9.32% syscall.Syscall
810ms 6.68% 60.43% 1860ms 15.33% bytes.(*Buffer).Write
620ms 5.11% 65.54% 6660ms 54.91% math/rand.(*Rand).Intn
570ms 4.70% 70.24% 570ms 4.70% runtime.procyield
500ms 4.12% 74.36% 9170ms 75.60% main.genSomeBytes
480ms 3.96% 78.32% 480ms 3.96% runtime.memmove
440ms 3.63% 81.95% 440ms 3.63% math/rand.(*rngSource).Uint64
(pprof)
依然会得到 cpu 性能的结果, 我们发现这次的结果与上次 30s 的结果百分比类似.
D.可视化查看
我们还是通过
$ go tool pprof ./demo4 profile
进入 profile 文件查看,然后我们输入web
指令.
$ go tool pprof ./demo4 profileFile: demo4
Type: cpu
Time: Mar 3, 2020 at 11:18pm (CST)
Duration: 30.13s, Total samples = 6.27s (20.81%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) web
这里如果报找不到graphviz
工具,需要安装一下
Ubuntu 安装
$sudo apt-get install graphviz
Mac 安装
brew install graphviz
windows 安装
下载graphviz.gitlab.io/_pages/Down…
将graphviz安装目录下的bin文件夹添加到Path环境变量中。 在终端输入dot -version查看是否安装成功。
然后我们得到一个 svg 的可视化文件在/tmp
路径下
这样我们就能比较清晰的看到函数之间的调用关系,方块越大的表示 cpu 的占用越大.
### 关于作者:
mail: danbing.at@gmail.com github: github.com/aceld 原创书籍 gitbook: legacy.gitbook.com/@aceld
创作不易, 共同学习进步, 欢迎关注作者, 回复"zinx"有好礼
文章推荐
开源软件作品
(原创开源) Zinx-基于 Golang 轻量级服务器并发框架-完整版 (附教程视频)
(原创开源) Lars-基于 C++ 负载均衡远程调度系统-完整版
精选文章
更多原创文章干货分享,请关注公众号
- 加微信实战群请加微信(注明:实战群):gocnio