go 程序性能调优 pprof 的使用（一）

OStack程序员社区-中国程序员成长平台 › 门户 › 编程› Go›Go教程

原作者: [db:作者] 来自: [db:来源] 收藏邀请

pprof是go语言内置的分析性能，分析数据的工具，pprof开启后，每隔一段时间（10ms）就会收集下当前的堆栈信息，获取格格函数占用的CPU以及内存资源；最后通过对这些采样数据进行分析，形成一个性能分析报告。pprof用 profile.proto 读取分析样本的集合，并声称可视化报告，以帮助分析数据（支持文本和图形报告）

profile.proto 是一个 Protobuf v3的描述文件，它描述了一组 callstack和 symbolization 信息，它的作用是统计分析一组采样的调用栈，配置文件格式是 stacktrace.

采样方式

runtime/pprof 采集程序（非server）指定区块的运行数据进行分析
net/http/pprof 基于 http server 运行，并且可以采集运行时的数据进行分析（其实net/http/pprof中只是使用runtime/pprof包来进行封装了一下，并在http端口上暴露出来）
go test 通过运行测试用例，指定所需标识进行采集

使用模式

Report Generation 报告生成
InteractiveTerminal Use 交互式终端使用
web interface web界面

可以做什么

CPU profiling cpu分析，按照一定的频率采集所监听的应用程序cpu（含寄存器）的使用情况，确定应用程序在主动消耗cpu周期时花费时间的位置
Memory Profiling 内存分析,在应用程序进行堆分配记录堆栈跟踪，用于监听当前和历史内存使用情况，以及检查内存泄漏。
Block Profiling 阻塞分析，记录goroutine 阻塞等待同步（包含定时器通道）的位置，默认不开启，需要调用 runtime.SetBlockProfileRate 进行设置
Mutex Profiling 互斥锁分析。报告互斥锁的竞争情况，默认不开启，需要调用 runtime.SetMutexProfileFraction 进行设置

简单例子

package main
import (
   "log"
   "net/http"
   _ "net/http/pprof"
   "time"
)
var datas []string
func main() {
   go func() {
      for  {
         log.Printf("len:%d",Add("gwyy"))
         time.Sleep(time.Microsecond + 10)
      }
   }()
   _ = http.ListenAndServe(":6060",nil)
}
func Add(str string) int {
   data := []byte(str)
   datas = append(datas,string(data))
   return len(datas)
}

为什么要初始化 net/http/pprof

在前面例子中，在引用上对 net/http/pprof 包进行了默认的初始化，（也就是 _），如果没在对该包进行初始化，则无法调用pprof的相关接口，这是为什么呢，我们可以一起看看该包初始化方法：

func init() {
   http.HandleFunc("/debug/pprof/", Index)
   http.HandleFunc("/debug/pprof/cmdline", Cmdline)
   http.HandleFunc("/debug/pprof/profile", Profile)
   http.HandleFunc("/debug/pprof/symbol", Symbol)
   http.HandleFunc("/debug/pprof/trace", Trace)
}

实际上，在初始化函数中， net/http/pprof 会对标准库中的 net/http 默认提供 DefaultServeMux 进行路由注册，源码如下

func HandleFunc(pattern string, handler func(ResponseWriter, *Request)) {
   DefaultServeMux.HandleFunc(pattern, handler)
}

我们在例子中使用的 HTTP Server,也是标准库默认提供的，因此便可以注册进去。

在实际项目中我们有独立的 ServeMux的，这时候只需要将PProf对应的路由注册进去即可　　

mux := http.NewServeMux()
mux.HandleFunc("/debug/pprof",pprof.Index)
mux.HandleFunc("/debug/pprof/cmdline"，pprof.cmdline)
mux.HandleFunc("/debug/pprof/profile", pprof.Profile)
mux.HandleFunc("/debug/pprof/symbol", pprof.Symbol)
mux.HandleFunc("/debug/pprof/trace", pprof.Trace)

好了我们运行了上面的程序后，浏览器直接访问：

http://127.0.0.1:6060/debug/pprof/

如果在访问路径上加上 ?debug=1 则可以直接在浏览器中访问。

这个页面中有许多子页面，咱们继续深究下去，看看可以得到什么？

profile（CPU Profiling）: $HOST/debug/pprof/profile，默认进行 30s 的 CPU Profiling，得到一个分析用的 profile 文件
allocs 查看过去所有内存分配样本，访问路径为 /debug/pprof/allocs
cmdline 当前程序命令行的完整调用路径
block（Block Profiling）：$HOST/debug/pprof/block，查看导致阻塞同步的堆栈跟踪
goroutine：$HOST/debug/pprof/goroutine，查看当前所有运行的 goroutines 堆栈跟踪
heap（Memory Profiling）: $HOST/debug/pprof/heap，查看活动对象的内存分配情况
mutex（Mutex Profiling）：$HOST/debug/pprof/mutex，查看导致互斥锁的竞争持有者的堆栈跟踪
threadcreate：$HOST/debug/pprof/threadcreate，查看创建新OS线程的堆栈跟踪

一般在线上环境，为了网络安全，通常不会这么做。另外debug的访问方式是具有时效性的，在实际场景中，我们常常需要及时将当前状态下的 profile文件给存储下来，便于二次分析。

通过终端访问

第二种是通过命令行完整对正在运行的程序 pprof进行抓取和分析

//在执行命令后，需要等待 60s （可以调整seconds的值） PProf 会进行 cpu Profiling , 结束后将默认进入PProf 的命令行交互模式，查看或者导出分析结果。
// 如果是以TLS方式启动的HTTP Server 那么在调用需要改成 go tool pprof https+insecure://localhost:6060/debug/pprof/profile?seconds=60
go tool pprof http://localhost:6060/debug/pprof/profile?seconds=60
Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile?seconds=60
Saved profile in C:\Users\admin\pprof\pprof.samples.cpu.001.pb.gz
Type: cpu
Time: Oct 12, 2020 at 11:40pm (CST)
Duration: 1mins, Total samples = 13.53s (22.50%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)

top命令

输入命令 top 10 查看对应资源开销（例如 cpu就是执行耗时/开销 Memory 就是内存占用大小）排名前十的函数

(pprof) top 10
Showing nodes accounting for 10.82s, 79.97% of 13.53s total
Dropped 64 nodes (cum <= 0.07s)
Showing top 10 nodes out of 61
      flat  flat%   sum%        cum   cum%
     7.50s 55.43% 55.43%      7.56s 55.88%  runtime.stdcall1
     1.88s 13.90% 69.33%      1.90s 14.04%  runtime.cgocall
     0.31s  2.29% 71.62%      2.25s 16.63%  runtime.timerproc
     0.26s  1.92% 73.54%      0.26s  1.92%  runtime.(*mcache).prepareForSweep
     0.20s  1.48% 75.02%      0.53s  3.92%  runtime.acquirep
     0.18s  1.33% 76.35%      0.18s  1.33%  runtime.casgstatus
     0.15s  1.11% 77.46%      1.18s  8.72%  runtime.exitsyscall
     0.12s  0.89% 78.34%      0.52s  3.84%  runtime.goroutineReady
     0.11s  0.81% 79.16%      8.79s 64.97%  runtime.systemstack
     0.11s  0.81% 79.97%      0.11s  0.81%  runtime.unlock

flat：当前函数上运行耗时
flat%：函数自身占用的 CPU 运行耗时总比例
sum%：函数自身累积使用 CPU 总比例
cum：当前函数及其调用函数的运行总耗时
cum%：函数自身及其调用函数占 CPU 运行耗时总比例
最后一列为函数名称

大多数情况下，我们可以得出一个应用程序的运行情况，知道当前是什么函数，正在做什么事情，占用了多少资源等。

Heap Profiling

PS C:\Users\admin> go tool pprof http://localhost:6060/debug/pprof/heap
Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap
Saved profile in C:\Users\admin\pprof\pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.001.pb.gz
Type: inuse_space
Time: Oct 12, 2020 at 11:50pm (CST)
No samples were found with the default sample value type.
Try "sample_index" command to analyze different sample values.
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)

这个命令能够很快的拉取到结果。不需要采样等待，需要注意的是 Type 这个选项默认是 inuse_space，实际上，它可以对多种内存情况进行分析。常见的有：

inuse_space 分析应用常驻内存的占用情况

PS C:\Users\admin> go tool pprof  -inuse_space http://localhost:6060/debug/pprof/heap
Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap
Saved profile in C:\Users\admin\pprof\pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.002.pb.gz
Type: inuse_space
Time: Oct 12, 2020 at 11:52pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 3.38MB, 100% of 3.38MB total
      flat  flat%   sum%        cum   cum%
    2.38MB 70.40% 70.40%     2.38MB 70.40%  main.Add
       1MB 29.60%   100%     3.38MB   100%  main.main.func1

alloc_objects 分析应用程序的内存临时分配情况

PS C:\Users\admin> go tool pprof  -alloc_objects http://localhost:6060/debug/pprof/heap
Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap
Saved profile in C:\Users\admin\pprof\pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.003.pb.gz
Type: alloc_objects
Time: Oct 12, 2020 at 11:53pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 98305, 100% of 98312 total
Dropped 14 nodes (cum <= 491)
      flat  flat%   sum%        cum   cum%
     98305   100%   100%      98311   100%  main.main.func1
(pprof)

另外还有 inuse_objects 和 alloc_space 类别，分别对应查看每个函数的对象数量和分配的内存空间大小。

Goroutine Profiling

PS C:\Users\admin> go tool pprof   http://localhost:6060/debug/pprof/goroutine
Fetching profile over HTTP from http://localhost:6060/debug/pprof/goroutine
Saved profile in C:\Users\admin\pprof\pprof.goroutine.001.pb.gz
Type: goroutine
Time: Oct 13, 2020 at 12:15am (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)

　　在查看goroutine 时可以使用traces命令，这个命令会打印出对应的所有调用栈，以及指标信息，通过这个命令我们可以很方便的查看整改调用链路有什么，分别在哪里使用了多岁个goroutine,并且通过分析可以知道谁才是真正的调用方，输出结果如下：

(pprof) traces
Type: goroutine
Time: Oct 13, 2020 at 12:15am (CST)
-----------+-------------------------------------------------------
         1   runtime.cgocall
             syscall.Syscall9
             syscall.WSARecv
             internal/poll.(*FD).Read.func1
             internal/poll.(*ioSrv).ExecIO
             internal/poll.(*FD).Read
             net.(*netFD).Read
             net.(*conn).Read
             net/http.(*connReader).backgroundRead
-----------+-------------------------------------------------------
         1   runtime.gopark
             runtime.netpollblock
             internal/poll.runtime_pollWait
             internal/poll.(*pollDesc).wait
             internal/poll.(*ioSrv).ExecIO
             internal/poll.(*FD).acceptOne
             internal/poll.(*FD).Accept
             net.(*netFD).accept
             net.(*TCPListener).accept
             net.(*TCPListener).Accept
             net/http.(*Server).Serve
             net/http.(*Server).ListenAndServe
             net/http.ListenAndServe
             main.main
             runtime.main
-----------+-------------------------------------------------------
         1   runtime.gopark
             runtime.goparkunlock
             time.Sleep
             main.main.func1
-----------+-------------------------------------------------------
         1   runtime/pprof.writeRuntimeProfile
             runtime/pprof.writeGoroutine
             runtime/pprof.(*Profile).WriteTo
             net/http/pprof.handler.ServeHTTP
             net/http/pprof.Index
             net/http.HandlerFunc.ServeHTTP
             net/http.(*ServeMux).ServeHTTP
             net/http.serverHandler.ServeHTTP
             net/http.(*conn).serve
-----------+-------------------------------------------------------
(pprof)

调用栈上的展示是自下而上的，也就是说 runtime.main方法调用了 main.main方法，而main.main方法又调用了 net/http.ListenAndServe 方法，排查起来比较方便。

每个调用栈信息都是用 ------- 分割，函数方法前面的是指标数据，例如，Gorutine Profiling 展示的是该方法占用的 goroutine的数量，而Heap Profiling 展示的是占用内存大小。如图

PS C:\Users\admin> go tool pprof   http://localhost:6060/debug/pprof/heap
Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap
Saved profile in C:\Users\admin\pprof\pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.005.pb.gz
Type: inuse_space
Time: Oct 13, 2020 at 12:24am (CST)
No samples were found with the default sample value type.
Try "sample_index" command to analyze different sample values.
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) traces
Type: inuse_space
Time: Oct 13, 2020 at 12:24am (CST)
-----------+-------------------------------------------------------
     bytes:  304kB
  678.95kB   main.Add
             main.main.func1
-----------+-------------------------------------------------------
     bytes:  192kB
         0   main.Add
             main.main.func1
-----------+-------------------------------------------------------
(pprof)

实际上，PProf中的所有功能都会根据 Profile的不同类型展示不同的对应结果

Mutex Profiling

一般来说，在调用 chan （通道）、sync.Mutex （同步锁）或者 time.Sleep() 时会造成阻塞，下面看个例子：

func init() {
   runtime.SetMutexProfileFraction(1)
}
func main() {
   var m sync.Mutex
   var datas = make(map[int]struct{})
   for i:=0;i<999;i++ {
      go func(i int) {
         m.Lock()
         defer m.Unlock()
         datas[i] = struct{}{}
      }(i)
   }
   _ = http.ListenAndServe(":6060",nil)
}

需要特别注意的是 runtime.SetMutexProfileFraction(1) 语句，如果未来希望对互斥锁进行采集，则需要调用该方法设置采集频率，如果没有设置，或者设置数值小于0，则不进行采集

接下里调用 go tool pprof 进行分析：

PS C:\Users\admin> go tool pprof   http://localhost:6060/debug/pprof/mutex
Fetching profile over HTTP from http://localhost:6060/debug/pprof/mutex
Saved profile in C:\Users\admin\pprof\pprof.contentions.delay.001.pb.gz
Type: delay
Time: Oct 13, 2020 at 12:31am (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)

调用 top 命令，查看互斥锁排名

(pprof) top
Showing nodes accounting for 149.51us, 100% of 149.51us total
      flat  flat%   sum%        cum   cum%
  149.51us   100%   100%   149.51us   100%  sync.(*Mutex).Unlock
         0     0%   100%   149.51us   100%  main.main.func1
(pprof)

调用 list命令查看指定函数的代码情况（包含特定的指标信息，如耗时）若函数名不明确，则默认对该函数名进行模糊匹配：

(pprof) list main
Total: 149.51us
ROUTINE ======================== main.main.func1 in D:\goroot\projects\_practice\go-learn\pprof\main.go
         0   149.51us (flat, cum)   100% of Total
         .          .     16:   for i:=0;i<999;i++ {
         .          .     17:           go func(i int) {
         .          .     18:                   m.Lock()
         .          .     19:                   defer m.Unlock()
         .          .     20:                   datas[i] = struct{}{}
         .   149.51us     21:           }(i)
         .          .     22:   }
         .          .     23:   _ = http.ListenAndServe(":6060",nil)
         .          .     24:}
(pprof)

从输出分析中可以看到引起互斥锁函数，以及锁开销的位置。

Block Profiling

与 Mutex 的 runtime.SetMutexProfileFraction 语句类似，Block也需要调用 runtime.SetBlockProfileRate 语句进行设置，如果没有设置，或者设置数值小于0，则不进行采集

func init() {
   runtime.SetMutexProfileFraction(1)
   runtime.SetBlockProfileRate(1)
}

调用 top 命令，查看阻塞情况排名：

PS C:\Users\admin> go tool pprof   http://localhost:6060/debug/pprof/block
Fetching profile over HTTP from http://localhost:6060/debug/pprof/block
Saved profile in C:\Users\admin\pprof\pprof.contentions.delay.004.pb.gz
Type: delay
Time: Oct 13, 2020 at 12:35am (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 83.75us, 100% of 83.75us total
      flat  flat%   sum%        cum   cum%
   83.75us   100%   100%    83.75us   100%  sync.(*Cond).Wait
         0     0%   100%    83.75us   100%  net/http.(*conn).serve
         0     0%   100%    83.75us   100%  net/http.(*connReader).abortPendingRead
         0     0%   100%    83.75us   100%  net/http.(*response).finishRequest
(pprof)

也可以用 list 命令查看具体阻塞情况。调用方式和 Mutex Profiling 一样