1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52
|
GODEBUG=gctrace=1 ./go-pprof-practice | grep gc
gc 1 @0.003s 2%: 0.004+0.44+0.004 ms clock, 0.004+0.21/0.11/0+0.004 ms cpu, 16->16->0 MB, 17 MB goal, 1 P gc 2 @6.201s 0%: 0.041+2.9+0.004 ms clock, 0.041+0.31/0/0+0.004 ms cpu, 7->7->6 MB, 8 MB goal, 1 P gc 3 @6.204s 0%: 0.026+6.2+0.003 ms clock, 0.026+0.23/0/0+0.003 ms cpu, 14->14->12 MB, 15 MB goal, 1 P gc 4 @6.211s 0%: 0.038+10+0.003 ms clock, 0.038+0.23/0/0+0.003 ms cpu, 28->28->24 MB, 29 MB goal, 1 P gc 5 @6.223s 0%: 0.023+26+0.002 ms clock, 0.023+0/0.23/0+0.002 ms cpu, 56->56->48 MB, 57 MB goal, 1 P gc 6 @6.251s 0%: 0.038+47+0.003 ms clock, 0.038+0/0.25/0+0.003 ms cpu, 112->112->96 MB, 113 MB goal, 1 P gc 7 @6.301s 0%: 0.051+93+0.003 ms clock, 0.051+0/0.24/0+0.003 ms cpu, 224->224->192 MB, 225 MB goal, 1 P gc 8 @6.407s 0%: 0.023+192+0.004 ms clock, 0.023+0/0.28/0+0.004 ms cpu, 448->448->384 MB, 449 MB goal, 1 P gc 9 @6.631s 0%: 0.053+397+0.003 ms clock, 0.053+0/0.25/0+0.003 ms cpu, 896->896->768 MB, 897 MB goal, 1 P gc 10 @7.080s 0%: 0.052+1205+0.003 ms clock, 0.052+0/0.24/0+0.003 ms cpu, 1792->1792->1536 MB, 1793 MB goal, 1 P
可以看到,GC 差不多每 3 秒就发生一次,且每次 GC 都会从 16MB 清理到几乎 0MB,说明程序在不断的申请内存再释放,这是高性能 golang 程序所不允许的。
所以接下来使用 pprof 排查时,我们在乎的不是什么地方在占用大量内存,而是什么地方在不停地申请内存,这两者是有区别的。
go tool pprof http://localhost:6060/debug/pprof/allocs
(pprof) top Showing nodes accounting for 16MB, 100% of 16MB total flat flat% sum% cum cum% 16MB 100% 100% 16MB 100% github.com/wolfogre/go-pprof-practice/animal/canidae/dog.(*Dog).Run (inline) 0 0% 100% 16MB 100% github.com/wolfogre/go-pprof-practice/animal/canidae/dog.(*Dog).Live 0 0% 100% 16MB 100% main.main 0 0% 100% 16MB 100% runtime.main
(pprof) list Run Total: 16MB ROUTINE ======================== github.com/wolfogre/go-pprof-practice/animal/canidae/dog.(*Dog).Run in /Users/liuwei/golang/pkg/mod/github.com/wolfogre/go-pprof-practice@v0.0.0-20190402114113-8ce266a210ee/animal/canidae/dog/dog.go 16MB 16MB (flat, cum) 100% of Total . . 38: log.Println(d.Name(), "pee") . . 39:} . . 40: . . 41:func (d *Dog) Run() { . . 42: log.Println(d.Name(), "run") 16MB 16MB 43: _ = make([]byte, 16 * constant.Mi) . . 44:} . . 45: . . 46:func (d *Dog) Howl() { . . 47: log.Println(d.Name(), "howl") . . 48:} 可以看到 github.com/wolfogre/go-pprof-practice/animal/canidae/dog.(*Dog).Run 会进行无意义的内存申请,而这个函数又会被频繁调用,这才导致程序不停地进行 GC
|