pprof是GoLang程序性能分析工具，prof是profile（画像）的缩写，用pprof我们可以分析下面9种数据
真正分析时常用4种
-
CPU Profiling：CPU 分析，按照一定的频率采集所监听的应用程序 CPU（含寄存器）的使用情况，可确定应用程序在主动消耗 CPU 周期时花费时间的位置
-
Memory Profiling：内存分析，在应用程序进行堆分配时记录堆栈跟踪，用于监视当前和历史内存使用情况，以及检查内存泄漏
-
Block Profiling：阻塞分析，记录 goroutine 阻塞等待同步（包括定时器通道）的位置
-
Mutex Profiling：互斥锁分析，报告互斥锁的竞争情况
做性能分析，第一步需要先获取数据，然后对数据进行分析。所以下面展示一下如何进行数据获取。
数据获取
数据获取的方法和应用的类型相关：
-
工具型应用：执行完任务就退出
-
服务型应用：一直运行，如web服务等
-
使用默认
ServerMux -
自定义
ServerMux -
开源web框架，如gin等
-
grpc类服务
工具形应用
工具形应用主要使用 runtime/pprof 库，将画像数据写入文件中。
package main
import (
"fmt"
"os"
"runtime/pprof"
)
func main() {
//CPU Profile
f, err := os.Create("./cpuprofile")
if err != nil {
fmt.Println(err)
return
}
defer f.Close()
pprof.StartCPUProfile(f)
defer pprof.StopCPUProfile()
//Memory Profile
fm, err := os.Create("./memoryprofile")
if err != nil {
fmt.Println(err)
return
}
defer fm.Close()
pprof.WriteHeapProfile(fm)
for i := 0; i < 100; i++ {
fmt.Println("程序员麻辣烫")
}
}
执行完后，会发现cpuprofile、memoryprofile文件，里面包含cpu、内存的画像。 runtime/pprof 直接支持这两种画像。
服务型应用
使用默认ServerMux
这种是指使用了默认的 http.DefaultServeMux，通常是代码直接使用 http.ListenAndServe("0.0.0.0:8000", nil)，第二个参数赋值为nil的情况。对于这种只需要在代码中添加一行，匿名引用**net/http/pprof**。
package main
import (
"fmt"
"net/http"
_ "net/http/pprof"
"strings"
)
func sayhelloName(w http.ResponseWriter, r *http.Request) {
r.ParseForm() //解析参数，默认是不会解析的
fmt.Println(r.Form) //这些信息是输出到服务器端的打印信息
fmt.Println("path", r.URL.Path)
fmt.Println("scheme", r.URL.Scheme)
fmt.Println(r.Form["url_long"])
for k, v := range r.Form {
fmt.Println("key:", k)
fmt.Println("val:", strings.Join(v, ""))
}
fmt.Fprintf(w, "Hello 程序员麻辣烫!")
}
func main() {
http.HandleFunc("/", sayhelloName) //设置访问的路由
err := http.ListenAndServe(":9090", nil) //设置监听的端口
if err != nil {
fmt.Printf("ListenAndServe: %s", err)
}
}
执行 http://localhost:9090/?url_long=111&url_long=222 可看到返回内容 “Hello 程序员麻辣烫!”。
执行 http://localhost:9090/debug/pprof/ 可看到画像信息，如图一所示。
使用自定义的ServerMux
这里解释一下ServerMux，它是HTTP包中的一个结构体，里面存储了指定路径和该路径对应的处理函数
type ServeMux struct {
mu sync.RWMutex
m map[string]muxEntry
es []muxEntry // slice of entries sorted from longest to shortest.
hosts bool // whether any patterns contain hostnames
}
HTTP包中Server的hander默认就是DefaultServeMux
type Server struct {
Addr string // TCP address to listen on, ":http" if empty
Handler Handler // handler to invoke, http.DefaultServeMux if nil
}
http.ListenAndServe函数可以传递handler，如果handler不为nil，则说明研发自定义了 ServerMux，否则用的是默认DefaultServeMux
// ListenAndServe always returns a non-nil error.
func ListenAndServe(addr string, handler Handler) error {
server := &Server{Addr: addr, Handler: handler}
return server.ListenAndServe()
}
ListenAndServe最终会调用到ServeHTTP函数，根据路径找到对应的执行函数，整个流程结束
func (sh serverHandler) ServeHTTP(rw ResponseWriter, req *Request) {
handler := sh.srv.Handler
if handler == nil {
handler = DefaultServeMux
}
if req.RequestURI == "*" && req.Method == "OPTIONS" {
handler = globalOptionsHandler{}
}
handler.ServeHTTP(rw, req)
}
net/http/pprof包中，有init函数
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)
}
所以如果使用默认ServerMux，则不需要注册，但是如果使用自定义的ServerMux，则需要增加注册后，才能获取到pprof。
r.HandleFunc("/debug/pprof/", pprof.Index)
r.HandleFunc("/debug/pprof/cmdline", pprof.Cmdline)
r.HandleFunc("/debug/pprof/profile", pprof.Profile)
r.HandleFunc("/debug/pprof/symbol", pprof.Symbol)
r.HandleFunc("/debug/pprof/trace", pprof.Trace)
这里就不编写代码了，因为自定义一个ServerMux虽然难度不大，但是还是有些耗时的。大家知道对这种情况如何添加pprof即可。
操作完成后，执行 http://localhost:9090/debug/pprof/ 可看到画像信息，如图一所示。
开源web框架
开源web框架很多，因为常用gin，此处就讲述一下如何在gin框架中使用pprof。
在gin中使用pprof比较简单:
-
直接引入
Gin项目组提供的gin-contrib/pprof包 -
调用pprof.Register®
package main
import (
"github.com/gin-contrib/pprof"
"github.com/gin-gonic/gin"
"net/http"
)
func Ping(c *gin.Context) {
c.String(http.StatusOK, "ok")
}
func main() {
r := gin.Default()
pprof.Register(r)
r.GET("/ping", Ping)
// Listen and Server in 0.0.0.0:8080
r.Run(":8082")
}
执行 http://localhost:8082/ping 可看到返回结果 “OK”
执行 http://localhost:8082/debug/pprof/ 可看到画像信息，如图一所示
之所以调用pprof.Register®后pprof相关路由可访问，是因为Register替我们做了路径注册的事情
// Register the standard HandlerFuncs from the net/http/pprof package with
// the provided gin.Engine. prefixOptions is a optional. If not prefixOptions,
// the default path prefix is used, otherwise first prefixOptions will be path prefix.
func Register(r *gin.Engine, prefixOptions ...string) {
RouteRegister(&(r.RouterGroup), prefixOptions...)
}
// RouteRegister the standard HandlerFuncs from the net/http/pprof package with
// the provided gin.GrouterGroup. prefixOptions is a optional. If not prefixOptions,
// the default path prefix is used, otherwise first prefixOptions will be path prefix.
func RouteRegister(rg *gin.RouterGroup, prefixOptions ...string) {
prefix := getPrefix(prefixOptions...)
prefixRouter := rg.Group(prefix)
{
prefixRouter.GET("/", pprofHandler(pprof.Index))
prefixRouter.GET("/cmdline", pprofHandler(pprof.Cmdline))
prefixRouter.GET("/profile", pprofHandler(pprof.Profile))
prefixRouter.POST("/symbol", pprofHandler(pprof.Symbol))
prefixRouter.GET("/symbol", pprofHandler(pprof.Symbol))
prefixRouter.GET("/trace", pprofHandler(pprof.Trace))
prefixRouter.GET("/allocs", pprofHandler(pprof.Handler("allocs").ServeHTTP))
prefixRouter.GET("/block", pprofHandler(pprof.Handler("block").ServeHTTP))
prefixRouter.GET("/goroutine", pprofHandler(pprof.Handler("goroutine").ServeHTTP))
prefixRouter.GET("/heap", pprofHandler(pprof.Handler("heap").ServeHTTP))
prefixRouter.GET("/mutex", pprofHandler(pprof.Handler("mutex").ServeHTTP))
prefixRouter.GET("/threadcreate", pprofHandler(pprof.Handler("threadcreate").ServeHTTP))
}
}
该项目地址为：https://github.com/shidawuhen/asap
grpc类服务
上面的几种服务型应用都能通过链接直接访问，如果是grpc这种类型的服务，如何使用pprof呢？
pprof做CPU分析原理是按照一定的频率采集程序CPU（包括寄存器）的使用情况，所以我们可以
-
在
gRPC服务启动时，异步启动一个监听其他端口的HTTP服务，通过这个HTTP服务间接获取gRPC服务的分析数据 -
因为gin使用默认的
ServerMux（服务复用器），所以只要匿名导入net/http/pprof包，这个HTTP的复用器默认就会注册pprof相关的路由
package main
import (
"context"
"log"
"net"
"net/http"
"google.golang.org/grpc"
pb "grpcservice/helloworld"
_ "net/http/pprof"
)
const (
port = ":50051"
portpprof = ":50052"
)
// server is used to implement helloworld.GreeterServer.
type server struct {
pb.UnimplementedGreeterServer
}
// SayHello implements helloworld.GreeterServer
func (s *server) SayHello(ctx context.Context, in *pb.HelloRequest) (*pb.HelloReply, error) {
log.Printf("Received: %v", in.GetName())
return &pb.HelloReply{Message: "Hello " + in.GetName()}, nil
}
func main() {
//pprof
go func() {
http.ListenAndServe(portpprof, nil)
}()
lis, err := net.Listen("tcp", port)
if err != nil {
log.Fatalf("failed to listen: %v", err)
}
s := grpc.NewServer()
pb.RegisterGreeterServer(s, &server{})
if err := s.Serve(lis); err != nil {
log.Fatalf("failed to serve: %v", err)
}
}
github地址为：https://github.com/shidawuhen/grpcservice (以前学习时的demo竟然用到新文章上，开心)
执行 http://localhost:50052/debug/pprof/ 可看到画像信息，如图一所示
PS：通过分析上面几种类型，可以看出对于服务型应用，核心在于将pprof的路由注册到服务中，并能提供访问。
数据分析
虽然我们生成了数据，这些数据可以存储到文件里、也可以展示在浏览器中。
但是直接访问这些性能分析数据，我们是分析不过来什么的。Go在1.11版本后在它自带的工具集go tool里内置了pprof工具来分析由pprof库生成的数据文件。
使用go tool pprof分析数据，主要有两种写法：
-
通过路径，如go tool pprof http://localhost:8082/debug/pprof/profile （进入命令行交互模式）
-
通过下载的文件，如go tool pprof cpuprofile （进入命令行交互模式）或者 go tool pprof -http=:9091 cpuprofile（进入web页面）
进入命令行交互模式后，可以使用help查看所有子命令，使用help <cmd|option>查看子命令使用方法。
(pprof) help
Commands:
callgrind Outputs a graph in callgrind format
comments Output all profile comments
(pprof) help top
Outputs top entries in text form
Usage:
top [n] [focus_regex]* [-ignore_regex]* [-cum] >f
具体选择哪种根据自己需要使用，本文都是用通过路径的方案进行分析，使用https://github.com/shidawuhen/asap中的代码。
CPU Profiling
先来看profile，访问/debug/pprof/profile这个链接会自动进行 CPU profiling，持续 30s，并生成一个文件供下载，可以通过带参数?=seconds=60进行60秒的数据采集。
为了模拟请求，使用ab进行压测，ab -k -c 1 -t 180 -n 100000000 http://localhost:8082/limit/countreject
执行go tool pprof http://localhost:8082/debug/pprof/profile后，默认需要等30s才会显示交互
列出最耗时的地方
(pprof) top 20
Showing nodes accounting for 30.06s, 99.01% of 30.36s total
Dropped 52 nodes (cum <= 0.15s)
Showing top 20 nodes out of 78
flat flat% sum% cum cum%
8.74s 28.79% 28.79% 8.76s 28.85% syscall.syscall
5.99s 19.73% 48.52% 5.99s 19.73% runtime.pthread_cond_signal
4.46s 14.69% 63.21% 4.46s 14.69% runtime.pthread_cond_wait
3.25s 10.70% 73.91% 3.25s 10.70% runtime.kevent
2.25s 7.41% 81.32% 5.50s 18.12% runtime.netpoll
2s 6.59% 87.91% 2s 6.59% runtime.nanotime
1.44s 4.74% 92.65% 1.44s 4.74% runtime.usleep
0.68s 2.24% 94.89% 0.68s 2.24% runtime.pthread_cond_timedwait_relative_np
0.55s 1.81% 96.71% 1.23s 4.05% runtime.notetsleep
0.50s 1.65% 98.35% 0.67s 2.21% net/http.(*connReader).backgroundRead
0.11s 0.36% 98.72% 11.24s 37.02% runtime.findrunnable
0.04s 0.13% 98.85% 4.52s 14.89% runtime.stopm
0.03s 0.099% 98.95% 0.23s 0.76% runtime.runqgrab
0.02s 0.066% 99.01% 5.48s 18.05% internal/poll.(*FD).Write
0 0% 99.01% 2.84s 9.35% asap/aredis.(*RedisManager).Do
0 0% 99.01% 2.84s 9.35% asap/aredis.(*RedisManager).Incr
0 0% 99.01% 2.84s 9.35% asap/aredis.(*RedisManager).Incr.func1
0 0% 99.01% 2.84s 9.35% asap/aredis.(*RedisManager).redialDo
0 0% 99.01% 3.10s 10.21% asap/controller/limit.CountReject
0 0% 99.01% 1.50s 4.94% bufio.(*Reader).ReadLine
每一行表示一个函数的信息。
flat：函数在 CPU 上运行的时间
flat%：函数在CPU上运行时间的百分比
sum%：是从上到当前行所有函数累加使用 CPU 的比例，如第二行sum=48.52=28.79+19.73
cum：这个函数以及子函数运行所占用的时间，应该大于等于flat
cum%：这个函数以及子函数运行所占用的比例，应该大于等于flat%
最后一列：函数的名字
如果应用程序有性能问题，上面这些信息应该能告诉我们时间都花费在哪些函数的执行上。通过这些信息可以发现，redis操作所消耗的时间微乎其微。
生成函数调用图
在交互模式下输入 web，就能自动生成一个 svg 文件，并跳转到浏览器打开，生成了一个函数调用图，不过需要安装graphviz后才能使用，安装方法可参考 https://shidawuhen.github.io/2020/02/08/go-callvis/ 。
左上角方框内数据：表示显示的为cpu的画像。显示的节点在总共30.36s的抽样中，占30.06s，比例为99.01%。
图中每个方框对应应用程序运行的一个函数，方框越大代表函数执行的时间越久（函数执行时间会包含它调用的子函数的执行时间，但并不是正比的关系）；方框之间的箭头代表着调用关系，箭头上的数字代表被调用函数的执行时间。具体细节可以参考：https://github.com/google/pprof/tree/master/doc#interpreting-the-callgraph
方框中显示的时间为总时间，findrunnable的总执行时间为11.24s，总时间占比为37.02%，只算函数自身执行时间为0.11s，总时间占比为0.36%=(0.11/11.24)*37.02%。调用函数5.49+4.52+0.23+0.82=11.06约等于11.24-0.11=11.13。
通过函数调用图，可以很直观的看出哪个函数耗时严重。
分析函数代码
当确定出哪个函数耗时之后，可以用pprof分析函数中的哪一行导致的耗时，使用子命令：list 函数名。
(pprof) list CountReject
Total: 30.36s
ROUTINE ======================== asap/controller/limit.CountReject in /Users/bytedance/My/work/code/go/asap/controller/limit/countReject.go
0 3.10s (flat, cum) 10.21% of Total
. . 16:// @Router /limit/countreject [get]
. . 17:func CountReject(c *gin.Context) {
. . 18: currentTime := time.Now().Unix()
. . 19: key := fmt.Sprintf("count:%d", currentTime)
. . 20: limitCount := 5
. 250ms 21: fmt.Println(key)
. 2.84s 22: trafficCount, _ := aredis.GetRedis(aredis.BASEREDIS).Incr(key)
. . 23: if trafficCount == 1 {
. . 24: aredis.GetRedis(aredis.BASEREDIS).Expire(key, 86400)
. . 25: }
. . 26: if int(trafficCount) > limitCount {
. 10ms 27: c.String(http.StatusBadGateway, "reject")
. . 28: return
. . 29: }
. . 30: c.String(http.StatusOK, "ok")
. . 31:}
可以看出，对于CountReject函数，耗时的位置主要在第22行，请求Redis的操作。
Memory Profiling
memory profiling主要查看程序当前活动对象内存分配。使用方法和CPU Profiling一样，
执行go tool pprof http://localhost:8082/debug/pprof/heap
列出最耗内存的地方
仍然使用top命令，可以看出最耗内存的位置是：golang.org/x/net/webdav.(*memFile).Write
(pprof) top 20
Showing nodes accounting for 16250.09kB, 100% of 16250.09kB total
flat flat% sum% cum cum%
14704.35kB 90.49% 90.49% 14704.35kB 90.49% golang.org/x/net/webdav.(*memFile).Write
1024.38kB 6.30% 96.79% 1024.38kB 6.30% runtime.malg
521.37kB 3.21% 100% 521.37kB 3.21% golang.org/x/net/webdav/internal/xml.init
0 0% 100% 2154.28kB 13.26% github.com/swaggo/gin-swagger/swaggerFiles.init.12
0 0% 100% 1574.07kB 9.69% github.com/swaggo/gin-swagger/swaggerFiles.init.5
0 0% 100% 10976kB 67.54% github.com/swaggo/gin-swagger/swaggerFiles.init.6
0 0% 100% 15225.72kB 93.70% runtime.doInit
0 0% 100% 15225.72kB 93.70% runtime.main
0 0% 100% 1024.38kB 6.30% runtime.mstart
0 0% 100% 1024.38kB 6.30% runtime.newproc.func1
0 0% 100% 1024.38kB 6.30% runtime.newproc1
0 0% 100% 1024.38kB 6.30% runtime.systemstack
每一列的含义和CPU Profiling中表达的一致，只不过这里显示的是内存。
生成函数调用图
使用web命名，能够生成函数调用图，只不过显示的内容为内存维度
在这个代码里，我使用了swagger，在所有环境里都是打开的，所以看一下这个消耗可以发现生产环境确实是没必要开，浪费空间。
分析函数代码
仍然使用list 函数名，如list runtime.malg
(pprof) list runtime.malg
Total: 15.87MB
ROUTINE ======================== runtime.malg in /usr/local/go/src/runtime/proc.go
1MB 1MB (flat, cum) 6.30% of Total
. . 3227: execLock.unlock()
. . 3228:}
. . 3229:
. . 3230:// Allocate a new g, with a stack big enough for stacksize bytes.
. . 3231:func malg(stacksize int32) *g {
1MB 1MB 3232: newg := new(g)
. . 3233: if stacksize >= 0 {
. . 3234: stacksize = round2(_StackSystem + stacksize)
. . 3235: systemstack(func() {
. . 3236: newg.stack = stackalloc(uint32(stacksize))
. . 3237: })
可以看到内存主要消耗的位置。
数据分析总结
使用profile可以获取很多重要信息，cpu profiling、memory profiling使用也是最频繁的。分析的时候，需要先获取到数据，通过web发现耗时的函数，然后通过list找到具体位置。
其它的数据的分析和CPU、Memory基本一致。下面列一下所有的数据类型：
-
http://localhost:8082/debug/pprof/ ：获取概况信息，即图一的信息
-
go tool pprof http://localhost:8082/debug/pprof/allocs : 分析内存分配
-
go tool pprof http://localhost:8082/debug/pprof/block : 分析堆栈跟踪导致阻塞的同步原语
-
go tool pprof http://localhost:8082/debug/pprof/cmdline : 分析命令行调用的程序，web下调用报错
-
go tool pprof http://localhost:8082/debug/pprof/goroutine : 分析当前 goroutine 的堆栈信息
-
go tool pprof http://localhost:8082/debug/pprof/heap : 分析当前活动对象内存分配
-
go tool pprof http://localhost:8082/debug/pprof/mutex : 分析堆栈跟踪竞争状态互斥锁的持有者
-
go tool pprof http://localhost:8082/debug/pprof/profile : 分析一定持续时间内CPU的使用情况
-
go tool pprof http://localhost:8082/debug/pprof/threadcreate : 分析堆栈跟踪系统新线程的创建
-
go tool pprof http://localhost:8082/debug/pprof/trace : 分析追踪当前程序的执行状况
总结
希望大家在生产环境中不会用到pprof，正常情况下，大部分问题都不需要用到pprof即可解决。使用pprof是有一定成本的，必须要想办法先能获取到数据。
如果真的遇到线上问题必须使用pprof，建议先想好要分析哪类数据。
pprof对程序的性能优化还是很有利的，获取数据后，可以快速定位到耗时较多的位置进行优化，而且也支持只打印和某个函数相关的命令，很人性化。
资料
-
https: //studygolang.com/articles/26918#reply0
-
Golang 大杀器之性能剖析 PProf https://segmentfault.com/a/1190000016412013
-
http://docscn.studygolang.com/pkg/runtime/pprof/
-
https://github.com/google/pprof/blob/master/doc/README.md
-
https://github.com/google/pprof/tree/master/doc
-
pprof的使用 https://www.jianshu.com/p/f4690622930d
-
手把手教你使用pprof分析web项目（Golang）https://www.yuque.com/u12472119/wtxoi6/ny150b
最后
大家如果喜欢我的文章，可以关注我的公众号（程序员麻辣烫）
我的个人博客为：https://shidawuhen.github.io/
往期文章回顾：
招聘
设计模式
语言
架构
存储
网络
工具
读书笔记
思考
4544
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
