游戏里sp和ssr什么意思（一文搞懂pprof）

逗爷 2023-04-23 14:14:55 985

游戏里sp和ssr什么意思（一文搞懂pprof）执行 http://localhost:9090/debug/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)

pprof是golang程序性能分析工具，prof是profile（画像）的缩写，用pprof我们可以分析下面9种数据

游戏里sp和ssr什么意思（一文搞懂pprof）(1)

真正分析时常用4种

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

做性能分析，第一步需要先获取数据，然后对数据进行分析。所以下面展示一下如何进行数据获取。

1.数据获取

数据获取的方法和应用的类型相关：

工具型应用：执行完任务就退出
服务型应用：一直运行，如web服务等
使用默认 ServerMux
自定义 ServerMux
开源web框架，如gin等
grpc类服务

1.1工具形应用

工具形应用主要使用 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 直接支持这两种画像。

1.2服务型应用1.2.1使用默认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/ 可看到画像信息，如图一所示。

1.2.2使用自定义的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/ 可看到画像信息，如图一所示。

1.2.3开源web框架

开源web框架很多，因为常用gin，此处就讲述一下如何在gin框架中使用pprof。

在gin中使用pprof比较简单:

直接引入Gin项目组提供的gin-contrib/pprof包
调用pprof.Register(r)

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(r)后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

1.2.4grpc类服务

上面的几种服务型应用都能通过链接直接访问，如果是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的路由注册到服务中，并能提供访问。

2.数据分析

虽然我们生成了数据，这些数据可以存储到文件里、也可以展示在浏览器中。

但是直接访问这些性能分析数据，我们是分析不过来什么的。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中的代码。

2.1CPU 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才会显示交互

2.1.1列出最耗时的地方

(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操作所消耗的时间微乎其微。

2.1.2生成函数调用图

在交互模式下输入 web，就能自动生成一个 svg 文件，并跳转到浏览器打开，生成了一个函数调用图，不过需要安装graphviz后才能使用，安装方法可参考 https://shidawuhen.github.io/2020/02/08/go-callvis/ 。

游戏里sp和ssr什么意思（一文搞懂pprof）(2)

左上角方框内数据：表示显示的为cpu的画像。显示的节点在总共30.36s的抽样中，占30.06s，比例为99.01%。

图中每个方框对应应用程序运行的一个函数，方框越大代表函数执行的时间越久（函数执行时间会包含它调用的子函数的执行时间，但并不是正比的关系）；方框之间的箭头代表着调用关系，箭头上的数字代表被调用函数的执行时间。具体细节可以参考：https://github.com/google/pprof/tree/master/doc#interpreting-the-callgraph

游戏里sp和ssr什么意思（一文搞懂pprof）(3)

方框中显示的时间为总时间，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。

通过函数调用图，可以很直观的看出哪个函数耗时严重。

2.1.3分析函数代码

当确定出哪个函数耗时之后，可以用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的操作。

2.2Memory Profiling

memory profiling主要查看程序当前活动对象内存分配。使用方法和CPU Profiling一样，

执行go tool pprof http://localhost:8082/debug/pprof/heap

2.2.1列出最耗内存的地方

仍然使用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中表达的一致，只不过这里显示的是内存。

2.2.2生成函数调用图

使用web命名，能够生成函数调用图，只不过显示的内容为内存维度

游戏里sp和ssr什么意思（一文搞懂pprof）(4)

在这个代码里，我使用了swagger，在所有环境里都是打开的，所以看一下这个消耗可以发现生产环境确实是没必要开，浪费空间。

2.2.3分析函数代码

仍然使用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: })

可以看到内存主要消耗的位置。

2.3数据分析总结

使用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 : 分析追踪当前程序的执行状况

3.总结

希望大家在生产环境中不会用到pprof，正常情况下，大部分问题都不需要用到pprof即可解决。使用pprof是有一定成本的，必须要想办法先能获取到数据。

如果真的遇到线上问题必须使用pprof，建议先想好要分析哪类数据。

pprof对程序的性能优化还是很有利的，获取数据后，可以快速定位到耗时较多的位置进行优化，而且也支持只打印和某个函数相关的命令，很人性化。

资料