mirror of
https://github.com/unknwon/the-way-to-go_ZH_CN.git
synced 2025-08-12 00:11:36 +08:00
137 lines
5.2 KiB
Markdown
137 lines
5.2 KiB
Markdown
# 13.10 性能调试：分析并优化 Go 程序
|
||
|
||
## 13.10.1 时间和内存消耗
|
||
|
||
可以用这个便捷脚本 *xtime* 来测量：
|
||
|
||
```sh
|
||
#!/bin/sh
|
||
/usr/bin/time -f '%Uu %Ss %er %MkB %C' "$@"
|
||
```
|
||
|
||
在 Unix 命令行中像这样使用 ```xtime goprogexec```，这里的 progexec 是一个 Go 可执行程序，这句命令行输出类似：56.63u 0.26s 56.92r 1642640kB progexec，分别对应用户时间，系统时间，实际时间和最大内存占用。
|
||
|
||
## 13.10.2 用 go test 调试
|
||
|
||
如果代码使用了 Go 中 `testing` 包的基准测试功能，我们可以用 gotest 标准的 `-cpuprofile` 和 `-memprofile` 标志向指定文件写入 CPU 或 内存使用情况报告。
|
||
|
||
使用方式：```go test -x -v -cpuprofile=prof.out -file x_test.go```
|
||
|
||
编译执行 x_test.go 中的测试，并向 prof.out 文件中写入 cpu 性能分析信息。
|
||
|
||
## 13.10.3 用 pprof 调试
|
||
|
||
你可以在单机程序 progexec 中引入 `runtime/pprof` 包；这个包以 pprof 可视化工具需要的格式写入运行时报告数据。对于 CPU 性能分析来说你需要添加一些代码：
|
||
|
||
```go
|
||
var cpuprofile = flag.String("cpuprofile", "", "write cpu profile to file")
|
||
|
||
func main() {
|
||
flag.Parse()
|
||
if *cpuprofile != "" {
|
||
f, err := os.Create(*cpuprofile)
|
||
if err != nil {
|
||
log.Fatal(err)
|
||
}
|
||
pprof.StartCPUProfile(f)
|
||
defer pprof.StopCPUProfile()
|
||
}
|
||
...
|
||
```
|
||
|
||
代码定义了一个名为 cpuprofile 的 flag，调用 Go flag 库来解析命令行 flag，如果命令行设置了 cpuprofile flag，则开始 CPU 性能分析并把结果重定向到那个文件（`os.Create` 用拿到的名字创建了用来写入分析数据的文件）。这个分析程序最后需要在程序退出之前调用 `StopCPUProfile()` 来刷新挂起的写操作到文件中；我们用 `defer` 来保证这一切会在 `main()` 返回时触发。
|
||
|
||
现在用这个 flag 运行程序：```progexec -cpuprofile=progexec.prof```
|
||
|
||
然后可以像这样用 gopprof 工具：```gopprof progexec progexec.prof```
|
||
|
||
gopprof 程序是 Google pprofC++ 分析器的一个轻微变种；关于此工具更多的信息，参见[https://github.com/gperftools/gperftools](https://github.com/gperftools/gperftools) 。
|
||
|
||
如果开启了 CPU 性能分析，Go 程序会以大约每秒 100 次的频率阻塞，并记录当前执行的 goroutine 栈上的程序计数器样本。
|
||
|
||
此工具一些有趣的命令：
|
||
|
||
1）`topN`
|
||
|
||
用来展示分析结果中最开头的 N 份样本，例如：```top5```
|
||
它会展示在程序运行期间调用最频繁的 5 个函数，输出如下：
|
||
|
||
```
|
||
Total: 3099 samples
|
||
626 20.2% 20.2% 626 20.2% scanblock
|
||
309 10.0% 30.2% 2839 91.6% main.FindLoops
|
||
...
|
||
```
|
||
|
||
第 5 列表示函数的调用频度。
|
||
|
||
2）`web` 或 `web 函数名`
|
||
|
||
该命令生成一份 SVG 格式的分析数据图表，并在网络浏览器中打开它（还有一个 gv 命令可以生成 PostScript 格式的数据，并在 GhostView 中打开，这个命令需要安装 graphviz）。函数被表示成不同的矩形（被调用越多，矩形越大），箭头指示函数调用链。
|
||
|
||
3）`list 函数名` 或 `weblist 函数名`
|
||
|
||
展示对应函数名的代码行列表，第 2 列表示当前行执行消耗的时间，这样就很好地指出了运行过程中消耗最大的代码。
|
||
|
||
如果发现函数 `runtime.mallocgc`（分配内存并执行周期性的垃圾回收）调用频繁，那么是应该进行内存分析的时候了。找出垃圾回收频繁执行的原因，和内存大量分配的根源。
|
||
|
||
为了做到这一点必须在合适的地方添加下面的代码：
|
||
|
||
```go
|
||
var memprofile = flag.String("memprofile", "", "write memory profile to this file")
|
||
...
|
||
|
||
CallToFunctionWhichAllocatesLotsOfMemory()
|
||
if *memprofile != "" {
|
||
f, err := os.Create(*memprofile)
|
||
if err != nil {
|
||
log.Fatal(err)
|
||
}
|
||
pprof.WriteHeapProfile(f)
|
||
f.Close()
|
||
return
|
||
}
|
||
```
|
||
|
||
用 `-memprofile flag` 运行这个程序：```progexec -memprofile=progexec.mprof```
|
||
|
||
然后你可以像这样再次使用 gopprof 工具：```gopprof progexec progexec.mprof```
|
||
|
||
`top5`，`list 函数名` 等命令同样适用，只不过现在是以 Mb 为单位测量内存分配情况，这是 top 命令输出的例子：
|
||
|
||
```
|
||
Total: 118.3 MB
|
||
66.1 55.8% 55.8% 103.7 87.7% main.FindLoops
|
||
30.5 25.8% 81.6% 30.5 25.8% main.*LSG·NewLoop
|
||
...
|
||
```
|
||
|
||
从第 1 列可以看出，最上面的函数占用了最多的内存。
|
||
|
||
同样有一个报告内存分配计数的有趣工具：
|
||
|
||
```sh
|
||
gopprof --inuse_objects progexec progexec.mprof
|
||
```
|
||
|
||
对于 web 应用来说，有标准的 HTTP 接口可以分析数据。在 HTTP 服务中添加
|
||
|
||
```go
|
||
import _ "http/pprof"
|
||
```
|
||
|
||
会为 /debug/pprof/ 下的一些 URL 安装处理器。然后你可以用一个唯一的参数——你服务中的分析数据的 URL 来执行 gopprof 命令——它会下载并执行在线分析。
|
||
|
||
```sh
|
||
gopprof http://localhost:6060/debug/pprof/profile # 30-second CPU profile
|
||
gopprof http://localhost:6060/debug/pprof/heap # heap profile
|
||
```
|
||
|
||
在 Go-blog（引用 15）中有一篇很好的文章用具体的例子进行了分析：分析 Go 程序（2011年6月）。
|
||
|
||
## 链接
|
||
|
||
- [目录](directory.md)
|
||
- 上一节：[用（测试数据）表驱动测试](13.9.md)
|
||
- 下一章：[协程（goroutine）与通道（channel）](14.0.md)
|