一看就懂系列之Golang的pprof

时间 2020-03-03

标签一看系列 golang pprof 栏目 Go 繁體版

原文原文链接

前言

这是一篇给网友的文章，正好最近在研究分析golang的性能，我以为是时候来一个了断了。

正文

1.一句话简介

Golang自带的一款开箱即用的性能监控和分析工具。html

（全篇看的过程当中不必特地记忆、看完天然让你有不同的感受）linux

2.使用姿式？

2.1 runtime/pprof

手动调用runtime.StartCPUProfile/runtime.StopCPUProfile等API来进行数据的采集。git

优势：灵活性高、按需采集。github

使用场景：工具型应用（好比说定制化的分析小工具、集成到公司监控系统）golang

2.2 net/http/pprof

经过http服务来获取Profile采样文件。 import _ "net/http/pprof"web

优势：简单易用。浏览器

使用场景：在线服务（一直运行着的程序）sass

(net/http/pprof中只是使用runtime/pprof包来进行封装了一下，并在http端口上暴露出来)bash

2.3 go test

经过命令go test -bench . -cpuprofile cpu.prof来进行采集数据。svg

优势：针对性强、细化到函数

使用场景：进行某函数的性能测试

3 分析姿式？

3.1 数据采集

分析的基础是获得相应的采集文件。runtime/pprof 和 go test 这两个均为命令行采集获得（下文以分析cpu的进行举例））。而net/http/pprof经过接口的方式将数据突出。

1.go test的方式很简单，命令：go test -bench . -cpuprofile cpu.prof 就能够生成。

2.runtime/pprof，直接上一个最简单的代码。

package main

import (
	"fmt"
	"os"
	"runtime/pprof"
	"time"
)

// 一段有问题的代码
func do() {
	var c chan int
	for {
		select {
		case v := <-c:
			fmt.Printf("我是有问题的那一行，由于收不到值：%v", v)
		default:
		}
	}
}

func main() {

	// 建立分析文件
	file, err := os.Create("./cpu.prof")
	if err != nil {
		fmt.Printf("建立采集文件失败, err:%v\n", err)
		return
	}

	// 进行cpu数据的获取
	pprof.StartCPUProfile(file)
	defer pprof.StopCPUProfile()

	// 执行一段有问题的代码
	for i := 0; i < 4; i++ {
		go do()
	}
	time.Sleep(10 * time.Second)
}
复制代码

执行命令：

go run pprof.go
复制代码

而后会获得数据采集文件：cpu.prof。(这个文件后文会用到)

3.http的方式，上代码：

package main

import (
	"fmt"
	"net/http"
    _ "net/http/pprof"  // 第一步～
)

// 一段有问题的代码
func do() {
	var c chan int
	for {
		select {
		case v := <-c:
			fmt.Printf("我是有问题的那一行，由于收不到值：%v", v)
		default:
		}
	}
}

func main() {
	// 执行一段有问题的代码
	for i := 0; i < 4; i++ {
		go do()
	}
	http.ListenAndServe("0.0.0.0:6061", nil)
}
复制代码

经过代码中的关键两步，执行起来就能够经过 http://127.0.0.1:6061/debug/pprof/看到对应的数据啦～

3.2 数据内容

不论是前文哪一种方式获取，均可以进行分析。这里http的方式把能够看到的信息所有都列出来了。

类型	描述
allocs	内存分配状况的采样信息
blocks	阻塞操做状况的采样信息
cmdline	显示程序启动命令参数及其参数
goroutine	显示当前全部协程的堆栈信息
heap	堆上的内存分配状况的采样信息
mutex	锁竞争状况的采样信息
profile	cpu占用状况的采样信息，点击会下载文件
threadcreate	系统线程建立状况的采样信息
trace	程序运行跟踪信息

经过加粗的关键字，很直观能够看到能分析到的数据。

（后文将重点根据cpu的采样信息展开命令行和图形化页面的讨论，其他项将在实战中应用）

3.3 数据分析

3.3.1 命令行

核心命令：go tool pprof <binary> <source>

binary：表明二进制文件路径。

source：表明生成的分析数据来源，能够是本地文件（前文生成的cpu.prof），也能够是http地址（好比：go tool pprof http://127.0.0.1:6060/debug/pprof/profile）

须要注意的是：较大负载的状况下（要不就故意写故障代码，或者就模拟访问压力）获取的有效数据更有意义，若是处于空闲状态，获得的结果可能意义不大

开始分析前文生成的cpu.prof:

go tool pprof cpu.prof
复制代码

看到页面：

咱们的目标是分析cpu那里耗时比较多，这里和linux命令有点像也是输入： top

这个图要好好说说！因为我在理的时候，我以为要结合具体的图一块儿看，才更好理解，因此提供两种方式来生成图：

1.在前文的对话框中继续输入：web。便可生成pprof001.svg的页面。

2.执行命令：go tool pprof -pdf cpu.prof,会生成profile001.pdf的pdf文件。(参数可选text、pdf、svg)

无论哪一种形式，都会获得如下图片：

类型	描述	举例
flat	该函数占用CPU的耗时	selectnbrecv占用CPU的耗时是12.29s
flat%	该函数占用CPU的耗时的百分比	selectnbrecv耗时：12.29s，cpu总耗时：29.14，12.29/29.14=42.18
sum%	top命令中排在它上面的函数以及本函数flat%之和	chanrecv：42.18%+30.47% = 72.65%
cum	当前函数加上该函数调用以前的累计CPU耗时	chanrecv：8.88+0.54=9.42
cum%	当前函数加上该函数调用以前的累计CPU耗时的百分比	9.42/29.14=32.33%
最后一列	当前函数名称	-

发现途中越粗表明越有问题耗时越高，越可能存在问题。发现do函数有点问题。此时经过命令：list funcName，来进行查看具体的位置

发现有问题的行数在文中具体的位置，原来是卡住了，加上default休眠n秒便可解决。

关于mem的分析同cpu相似，本文不在赘述。

总结一下，至少要记住分析三步走：top -> list Func -> web

3.3.2 可视化页面

两种方式能够支持浏览器打开web站：

1.执行命令：go tool pprof -http=:6060 cpu.prof

Top （同前文gdb交互页面的top命令）

Graph（同前文gdb交互页面的web命令）

Flame Graph（火焰图）

这里的颜色是随机分布的，只是看起来像火焰。

调用顺序由上到下，每一块表明一个函数，越大表明占用 CPU 的时间更长。同时它也能够支持点击块深刻进行分析。

Peek（详细=树结构）

Source（同前文gdb交互页面的list FuncName命令）
Disassemble

4.游戏中实战

西游记中师徒四人西天取经，历经九九八十一难，方可取得真经。

这边已经为小伙伴弄好了取经小脚本：点我

直接在浏览器中执行./xiyouji，即可看到师徒四人一路上的吃喝拉撒。

4.1 第一难-CPU占用太高

首先先看看profile文件，看看有没有cpu的异常

go tool pprof http://localhost:6060/debug/pprof/profile
复制代码

猛然发现这个猪八戒在吃上面有点问题。

因而咱们看看，执行命令：list Drink

原来吃上面有问题，进行了1亿次的空循环，怪不得占CPU那么高。

咱们在看看大图：web

此时修复问题便可。（备注掉便可修复，后文同）

4.2 第二难-内存占用太高

从新编译事后，继续前行。接下来看看内存有没问题。

go tool pprof http://localhost:6060/debug/pprof/heap 
复制代码

发现沙和尚彷佛吃的比较多？

进一步看看为何：list Eat

原来这里进行了恶意的内存追加，直到容量见顶

继续看看图，再次确认下：web

修复代码便可。

4.3 第三难-频繁内存回收

咱们都知道gc的频繁处理会致使stw不断出现，是一个高性能的服务不能容忍的。

这边须要借助一个环境变量来启动gc的观察,

GODEBUG=gctrace=1 ./xiyouji 2>&1|grep gc
复制代码

这个信息的说明：

能够看到基本上3s左右就会触发一次gc，每次都会从16M->0，说明内存被不断的申请和释放。

经过内存的分配状况，能够看gc是否存在异常，若是一直占着100%或者很大比例那说明是有问题的。

执行命令：

go tool pprof http://localhost:6060/debug/pprof/allocs
复制代码

继续查看悟空怎么回事：list Shit

看大图：web

同前文，备注掉代码便可继续前行。

知识点：这边须要注意的是为何设置16m呢？简单说这样才能在逃逸分析的时候，内存的申请从栈跑到堆上，这样才能引发gc回收。（更多详情请查看我还没写的《一看就懂系列之Golang的逃逸分析》）

4.4 第四难-协程泄露

咱们发像goroutine好像有点偏多？是否是协程泄漏了？继续往下看。

查看goroutine状况：

go tool pprof http://localhost:6060/debug/pprof/goroutine
复制代码

看到一个引发了不少goroutine的函数，可是彷佛看不到人工添加的函数引起的问题。

继续追大图：web

原来是唐僧睡觉的时候有问题。

继续追查有问题的函数：list Sleep

解决掉问题，再看看http://127.0.0.1:6060/debug/pprof/,发现已经恢复正常。

4.5 第五难-锁的争用

有发现一个异常：goroutine已经降到了4个，为何还有一个锁的征用问题？

go tool pprof localhost:6060/debug/pprof/mutex
复制代码

能够看到，126行主协程在进行lock加锁后，立马再次加锁，可是解锁由另外一个协程去unlock，另外一个协程足足休眠1s，这里会致使阻塞，形成锁争用问题。

解决掉便可（备注它）

4.6 第六难-阻塞操做

解决完前文的问题后，发现：

除了锁形成阻塞外，居然还有其余逻辑形成阻塞，继续往下看。

go tool pprof localhost:6060/debug/pprof/block
复制代码

能够明显看到，这里不一样于前文的slepe阻塞，是一个channel阻塞，要等1s以后才有数据输出，致使这里程序阻塞了1s。

4.7 第七难-一场误会

解决完前文全部问题后，仍是发现block有1个？抱着严谨的态度，继续追查。

go tool pprof localhost:6060/debug/pprof/block
复制代码

原来是http监听，符合预期。

4.8 第八难-取得真经

通过前文的屡次操做，相信你已经很熟悉排查流程和能排查的内容了。

这里总结一下排查套路。

第一步：进入排除对应的gdb交互。

go tool pprof http://localhost:6060/debug/pprof/{填上你想查看的内容}
复制代码

内容关键字：

类型	描述
allocs	内存分配状况的采样信息
blocks	阻塞操做状况的采样信息
cmdline	显示程序启动命令参数及其参数
goroutine	显示当前全部协程的堆栈信息
heap	堆上的内存分配状况的采样信息
mutex	锁竞争状况的采样信息
profile	cpu占用状况的采样信息，点击会下载文件
threadcreate	系统线程建立状况的采样信息
trace	程序运行跟踪信息

第二步：三联招，top->list FuncName->web

经过占用比分析，查看具体代码行数，看大图确认。

第三步：解决问题。

（细心的同窗可能会发现没有对trace进行分析，这个请期待《一看就懂系列之Golang的trace》）

5.与测试命令共舞

测试分析特别简单，在原有的命令后加上-cpuprofile=cpu.prof或-memprofile=mem.prof就能够获得对应的数据采集文件啦，后面的事对于已经取得真经的你应该懂的

命令例子：go test -bench . -cpuprofile cpu.prof

参考文献

1.Golang 大杀器之性能剖析 PProf

2.golang pprof 实战

3.Go 程序的性能监控与分析 pprof

4.go pprof 性能分析

5.如何监控 golang 程序的垃圾回收