• runtime/pprof:以非server的模式进行数据分析
• net/http/pprof:以HTTP server的形式进行数据分析

PProf是什么

可视化分析性能工具 支持模式：

• 生成报告 report generation
• 交互式终端 Interactive terminal
• Web界面 Web Interface

可以做什么

• CPU Profiling：分析CPU性能，按照一定频率监测程序使用CPU的情况，确定消耗CPU时间的位置
• Memory Profiling：分析内存占用情况，记录内存分配时的堆栈跟踪
• Block Profiling：阻塞分析，记录goroutine阻塞等待同步的位置
• Mutex Profiling：互斥锁分析，报告互斥锁的竞争情况

使用方式

import (
    _ "net/http/pprof"
)
func main() {
    go func() {
        if err := http.ListenAndServe(":6060", nil); eil != nil {
            log.Fatal(err)
        }
        os.Exit(0)
    }()
}

使用_会自动注册handler到http server中，可以通过http服务获取采样报告。
启动一个协程开启一个http server，这里handler已经被注册。在6060端口就可以查看报告。

优化实战

wolfogre/go-pprof-practice: go pprof practice. (github.com)
运行起来，然后打开http://localhost:6060/debug/pprof/。

主要观察一下几个选项：

类型	描述	备注
allocs	内存分配情况的采样信息	可以用浏览器打开，但可读性不高
blocks	阻塞操作情况的采样信息	可以用浏览器打开，但可读性不高
goroutine	当前所有协程的堆栈信息	可以用浏览器打开，但可读性不高
heap	堆上内存使用情况的采样信息	可以用浏览器打开，但可读性不高
mutex	锁争用情况的采样信息	可以用浏览器打开，但可读性不高
profile	CPU 占用情况的采样信息	浏览器打开会下载文件

CPU占用高问题解决

打开任务管理器：

使用go tool pprof检查:
go tool pprof http://localhost:6060/debug/pprof/profile
等待一会后进入交互式终端，输入top命令：

找到CPU占用最高的调用是tiger.(Tiger).Eat。
输入list Eat：

定位到了第24行的循环，占用了大量的CPU时间。
图形化显示调用栈，这里需要用到工具graphviz。查看官网可以看到如何下载Download | Graphviz。
我在Windows平台下使用chocolatey包管理工具，输入命令choco install graphviz即可完成安装和环境变量的配置。
在交互式终端中输入web命令，产生一个.svg文件并打开。

其中占用CPU时间长的框也就越大。
输入exit退出交互式终端，处理CPU占用高的代码，这里直接注释掉空循环相关代码，重新go build。

内存占用高问题解决

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

这里把后缀改成heap。
再次使用top和list定位问题。

发现占用内存最多的是mouse.go的第60行。这里一直在像buffer中追加内存。
使用web查看。

解决此处的内存占用再次运行即可发现没有了相关的内存问题。

探索垃圾回收

频繁的GC对性能的影响也是很大的，使用godebug调试，并用grep筛选出gc相关的日志。

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

使用命令：

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

查看内存分配，然后top，list，web。

定位到代码：

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

这里的Mi是1024*1024，如果改成一个较小的值，不会引起频繁的GC，会分配到栈上。

协程泄露

已经有104个协程了，对于一个小型程序，不是很正常。

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

top、list、web

发现wolf.go中一直在申请协程。进行修复。

锁的争用

上面还有一个mutex的问题。

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

top、list、web

定位到代码：

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

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

这个锁由主协程上锁，由子协程解锁，子协程解锁前会等待一秒，那么主协程第二次上锁就需要阻塞。当然这并不一定是有问题的。