go 程序性能调优 pprof 的使用 (一)

pprof是go语言内置 的分析性能,分析数据的工具,pprof开启后,每隔一段时间(10ms)就会收集下当前的堆栈信息,获取格格函数占用的CPU以及内存资源;最后通过对这些采样数据进行分析,形成一个性能分析报告。pprof用 profile.proto 读取分析样本的集合,并声称可视化报告,以帮助分析数据 (支持文本和图形报告)
profile.proto 是一个 Protobuf v3的描述文件,它描述了一组 callstack和 symbolization 信息,它的作用是统计分析一组采样的调用栈,配置文件格式是 stacktrace.
 

采样方式

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

使用模式

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

可以做什么

    1. CPU profiling cpu分析,按照一定的频率采集所监听的应用程序cpu(含寄存器)的使用情况,确定应用程序在主动消耗cpu周期时花费时间的位置
    2. Memory Profiling 内存分析,在应用程序进行堆分配记录堆栈跟踪,用于监听当前和历史内存使用情况,以及检查内存泄漏。
    3. Block Profiling 阻塞分析,记录goroutine 阻塞等待同步(包含定时器通道)的位置,默认不开启,需要调用 runtime.SetBlockProfileRate 进行设置
    4. 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)

  

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

如果在访问路径上加上 ?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 一样

 
 
 
 
 
 

posted @ 2020-10-13 10:28  梁天  阅读(188)  评论(0编辑  收藏