Question

采集测试或运行数据，分析问题，针对性改进代码。

• 尽可能排除外在干扰，比如硬件和系统被抢用。
• 开启 profile 会导致性能损失。
• 不同 profile 可能存在干扰，每次采集一种。

目标类型：

​

• cpu ​
• alloc ​
• heap ​
• threadcreate ​
• goroutine ​
• block ​
• mutex ​

采样方式：

• 测试： go test -memprofile mem.out
• 在线： import _ "net/http/pprof" ​
• 手工： runtime/pprof ​

测试采样

$ go test -run NONE -bench . -memprofile mem.out net/http

• -cpuprofile ：执行时间。
• -memprofile ：内存分配。
• -blockprofile ：阻塞。
• -mutexprofile ：锁争用。

• -memprofilerate ： runtime.MemProfileRate ​
• -blockprofilerate ： runtime.SetBlockProfileRate ​
• -mutexprofilefraction ： runtime.SetMutexProfileFraction ​

命令行、服务、交互三种模式查看采样结果。

$ go tool pprof -top mem.out                  # 命令行参数。
$ go tool pprof -http 0.0.0.0:8080 mem.out    # 服务。推荐！

$ go tool pprof http.test mem.out             # 交互。

Type: alloc_space

(pprof) top 5

Showing nodes accounting for 4249.95MB, 68.54% of 6200.73MB total
Dropped 299 nodes (cum <= 31MB)
Showing top 5 nodes out of 72

      flat  flat%   sum%        cum   cum%
 1770.01MB 28.55% 28.55%  1770.01MB 28.55%  net/textproto.(*Reader)...
  811.70MB 13.09% 41.64%  3086.27MB 49.77%  net/http.readRequest
  701.10MB 11.31% 52.94%   701.10MB 11.31%  net/http.copyValues
  497.58MB  8.02% 60.97%   497.58MB  8.02%  net/http.readCookies
  469.56MB  7.57% 68.54%   469.56MB  7.57%  net/url.parse

• flat : 仅当前函数，不包括它调用的其他函数。
• sum : 列表前几行所占百分比总和。
• cum : 当前函数调用堆栈累计。

找出目标，用 peek 命令列出调用来源。

(pprof) peek malg
Showing nodes accounting for 6200.73MB, 100% of 6200.73MB total
----------------------------------------------------------+-------------
      flat  flat%   sum%        cum   cum%   calls calls% + context 	 	 
----------------------------------------------------------+-------------
                                            1.50MB   100% |   runtime.newproc1
    1.50MB 0.024% 0.024%     1.50MB 0.024%                | runtime.malg
----------------------------------------------------------+-------------

也可用 list 输出源码行样式，更直观定位。

(pprof) list malg

ROUTINE ======================== runtime.malg in proc.go
    1.50MB     1.50MB (flat, cum) 0.024% of Total
         .          .   4029:	execLock.unlock()
         .          .   4030:}
         .          .   4031:
         .          .   4032:// Allocate a new g, with a stack.
         .          .   4033:func malg(stacksize int32) *g {
    1.50MB     1.50MB   4034:	newg := new(g)
         .          .   4035:	if stacksize >= 0 {
         .          .   4036:		stacksize = round2(_StackSyst...
         .          .   4037:		systemstack(func() {
         .          .   4038:			newg.stack = stackalloc(uint...
         .          .   4039:		})

打开浏览器查看。

(pprof) web
(pprof) web malg   # 以 malg 为主，精简输出结果。

在线采样

向目标程序注入 net/http/pprof 包。

package main

import (
	"net/http"
	_ "net/http/pprof"
)

func main() {
	http.ListenAndServe(":6060", http.DefaultServeMux)
}

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

Saved profile in /root/pprof/pprof.objects.space.001.pb.gz
Type: space

(pprof) top

Showing nodes accounting for 1536.76kB, 100% of 1536.76kB total
Showing top 10 nodes out of 23

      flat  flat%   sum%        cum   cum%
  512.50kB 33.35% 33.35%   512.50kB 33.35%  runtime.allocm
  512.20kB 33.33% 66.68%   512.20kB 33.33%  runtime.malg

$ curl http://localhost:6060/debug/pprof/heap -o mem.out
$ go tool pprof mem.out

手工采集

在代码中调用相关函数。

package main

import (
	"runtime/pprof"
	"os"
)

 func main() {
 	pprof.StartCPUProfile(os.Stdout)
 	defer pprof.StopCPUProfile()

 	// 。。。
 }

执行跟踪

相比 profile 采样统计， trace 捕获一个时段内的执行事件。

• G 如何执行。
• GC 等核心事件。
• 不良的并行化。

$ go test -trace trace.out net/http             # 采样
$ go tool trace -http 0.0.0.0:8080 trace.out    # 服务

注入方式，指定采样时长。

$ curl http://localhost:8080/debug/pprof/trace?seconds=5 -o trace.out

手工方式。

package main

import (
	"os"
	"runtime/trace"
)

func main() {
	out, _ := os.Create("trace.out")
	defer out.Close()

	trace.Start(out)
	defer trace.Stop()

	test()
}

Diagnostics