实验准备

首先获取一个需要进行调优的代码，GitHub - wolfogre/go-pprof-practice: go pprof practice.，可以通过各种方式下载。

通过编译这个程序并且运行它，我的是Windows系统，在编译之后直接生成了可执行文件。

执行可执行文件之后，控制台一直在输出一些日志。

并且自己的内存资源一直在飙升,略微担心机器扛不住。

开始使用pprof

保持程序运行，打开浏览器访问 http://localhost:6060/debug/pprof/，可以看到如下页面：

类型	描述	备注
allocs	内存分配情况的采样信息	可以用浏览器打开，但可读性不高
blocks	阻塞操作情况的采样信息	可以用浏览器打开，但可读性不高
cmdline	显示程序启动命令及参数	可以用浏览器打开，这里会显示 `./go-pprof-practice`
goroutine	当前所有协程的堆栈信息	可以用浏览器打开，但可读性不高
heap	堆上内存使用情况的采样信息	可以用浏览器打开，但可读性不高
mutex	锁争用情况的采样信息	可以用浏览器打开，但可读性不高
profile	CPU 占用情况的采样信息	浏览器打开会下载文件
threadcreate	系统线程创建情况的采样信息	可以用浏览器打开，但可读性不高
trace	程序运行跟踪信息	浏览器打开会下载文件

由于上面这些信息对我们来说还是太缺乏直观性，所以需要借助 go tool pprof 命令来排查问题，这个命令是 go 原生自带的，所以不用额外安装。

排查问题

CPU 占用过高

我们通过命令go tool pprof http://localhost:6060/debug/pprof/profile进入pprof的交互式终端：

top命令

然后输入top查看对于占用CPU较高的一些调用：

每一行表示一个函数的信息。

flat：函数在 CPU 上运行的时间

flat%：函数在CPU上运行时间的百分比

sum%：是从上到当前行所有函数累加使用 CPU 的比例，如第二行sum=48.52=28.79+19.73

cum：这个函数以及子函数运行所占用的时间，应该大于等于flat

cum%：这个函数以及子函数运行所占用的比例，应该大于等于flat%

最后一列：函数的名字

很明显，CPU占用过高就是github.com/wolfogre/go-pprof-practice/animal/felidae/tiger.(*Tiger).Eat导致的。

list Eat命令

我们输入list Eat查看这个问题出现在代码的哪个地方。

从图中我们可以看到，24这个循环是死循环，占用了大量的CPU，所以问题找到了、

web命令

为了更好地观看调用栈信息，我们安装一个graphviz，查看[Download | Graphviz](https://graphviz.gitlab.io/download/)网站上找到自己对应操作系统的安装方法。安装完成后，我们在上面的交互式终端继续输入web命令。

至此我们就通过pprof学会了找到CPU占用的问题所在了，我们使用exit命令退出交互式终端，然后将找到问题的地方修改正确即可。

内存占用过高

我们将之前有问题的代码注释掉后重新编译该程序，然后再次运行。

从图中我们可以看出内存占用还是较高的，使用go tool pprof http://localhost:6060/debug/pprof/heap命令再次使用pprof命令，依次输入top、list来查找问题。

可以看到这次出现的问题在github.com/wolfogre/go-pprof-practice/animal/muridae/mouse.(*Mouse).Steal，这个程序可以看出一直占用这些内存不释放，使用web命令来查看图形化的展示。

现在我们同样是注释掉相关代码来解决这个问题。

频繁内存回收

重新编译，重新运行，发现内存占用比较正常了。

一般这样说大家都知道内存占用看起来正常，但实际上就不太正常，通过查看gc日志我们可以看出gc发生的很频繁，这说明程序在不断地进行申请内存在释放，所以还需要继续优化。
由于内存的申请与释放频度是需要一段时间来统计的，所以我们保证炸弹程序已经运行了几分钟之后，再运行命令.go tool pprof http://localhost:6060/debug/pprof/allocs进入pprof的使用，通过top. list Run. web等命令查看运行情况。

从top命令结果发现github.com/wolfogre/go-pprof-practice/animal/canidae/dog.(*Dog).Run (inline)占用内存较多，而通过程序我们发现它在不断申请内存，而且还会被调用，但是没有什么意义，所以程序会不断地gc。同样找到问题注释问题代码。

协程泄露

我们重新跑一下，发现协程的数量较多，因为这毕竟是一个小程序，我们再次使用go tool pprof http://localhost:6060/debug/pprof/goroutine来排查一下，步骤依然还是top、 list、 web命令。

通过list命令我们找到问题代码的所在，打开文件发现程序在不停地创建没有实际作用的协程。

func (w *Wolf) Drink() {  
log.Println(w.Name(), "drink")  
for i := 0; i < 10; i++ {  
go func() {  
time.Sleep(30 * time.Second)  
}()  
}  
}

程序在不停的创建，休眠30s后又反复调用，不断地创建十个协程，最后内存还是会崩溃掉的。我们修改代码后重新编译运行：

排查锁

使用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()
}

可以看到，这个锁由主协程 Lock，并启动子协程去 Unlock，主协程会阻塞在第二次 Lock 这儿等待子协程完成任务，但由于子协程足足睡眠了一秒，导致主协程等待这个锁释放足足等了一秒钟。所以我们根据实际需要更改代码，并且重新编译执行。

排查阻塞操作

使用go tool pprof http://localhost:6060/debug/pprof/block来排查一下，步骤依然还是top、 list、 web命令。

可以看到，阻塞操作位于 github.com/wolfogre/go-pprof-practice/animal/felidae/cat.(*Cat).Pee：

func (c *Cat) Pee() {  
log.Println(c.Name(), "pee")  

<-time.After(time.Second)  
}

不同于睡眠一秒，这里是从一个 channel 里读数据时，发生了阻塞，直到这个 channel 在一秒后才有数据读出，这就导致程序阻塞了一秒而非睡眠了一秒。

记录使用pprof性能调优 ｜ 青训营