如何获取运行的go程序的profile信息

marlonche · · 10867 次点击 · · 开始浏览    
这是一个创建于 的文章,其中的信息可能已经有所发展或是发生改变。

go程序从开始运行起,runtime就按照一定频率对内存分配进行采样记录:当内存分配每达到一定值(默认是512KB,由[`runtime.MemProfileRate`](https://golang.google.cn/pkg/runtime/#pkg-variables)设定), runtime就会记录下当前这次内存分配的大小,call stack等信息到profile里面。 而CPU的profile是从调用[`runtime/pprof包的pprof.StartCPUProfile()`](https://golang.google.cn/pkg/runtime/pprof/#StartCPUProfile)开始,到[`pprof.StopCPUProfile()`](https://golang.google.cn/pkg/runtime/pprof/#StopCPUProfile)结束,每1秒采样100次,每次采样时记录下当前正在执行的所有goroutine的call stack,某个函数在这些快照里面出现的次数越多就说明这个函数越耗时。 运行的go程序的所有profile信息都是通过在运行时调用[`runtime/pprof`](https://golang.google.cn/pkg/runtime/pprof/)和[`runtime/trace`](https://golang.google.cn/pkg/runtime/trace/)两个包的接口获取,调用这些接口的方式有直接调用和通过http请求间接调用两种,下面我们说明各种常用的profile信息以及它们的获取,使用方式。 #### 1. **当前所有goroutine的函数调用栈** **用处:** 查看当前有哪些goroutine在运行,数量对不对,有没有出现很多goroutine卡在同一个地方的情况,有没有死锁的情况,间隔的刷新页面看看各个goroutine数量变化情况,了解程序运行状况变化。 **通过http请求间接获取:** 在程序中引入包[`net/http/pprof`](https://golang.google.cn/pkg/net/http/pprof/)并只使用它的初始化: import _ "net/http/pprof" 这一句导致[`源码里面实际执行的是`](https://github.com/golang/go/blob/master/src/net/http/pprof/pprof.go#L71): 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) } 上面的url和处理函数都被[`注册到了http包的DefaultServeMux里面`](https://github.com/golang/go/blob/master/src/net/http/server.go#L2374),所以要想使用这些url就必须使用DefaultServeMux来监听某一端口: http.ListenAndServe(":9999", nil) 这里第一个参数可以是本机的任一端口,[`当第二个参数为nil时就使用http包的DefaultServeMux来监听并处理http请求`](https://golang.google.cn/pkg/net/http/#ListenAndServe), 或者当程序里面已经有自定义的ServeMux时,可以像上面的init函数那样把pprof的处理函数[`注册到自定义的ServeMux`](https://golang.google.cn/pkg/net/http/#ServeMux.HandleFunc)。 在程序里面添加上面的代码后,运行时我们可以通过浏览器或wget访问下面的http地址查看goroutine信息: http://localhost:9999/debug/pprof/goroutine?debug=1 或者进入index页面查看更多项: http://localhost:9999/debug/pprof **直接获取:** 不常用,可以查看[`源码`](https://github.com/golang/go/blob/master/src/net/http/pprof/pprof.go#L224) #### 2. **一段时间内的CPU profile** **用处:** 查看消耗CPU的热点函数,能否减少调用次数,能否避免重复计算。 **通过http请求间接获取:** 同第1点里面获取goroutine信息一样,在程序中引入包[`net/http/pprof`](https://golang.google.cn/pkg/net/http/pprof/)并只使用它的初始化: import _ "net/http/pprof" 然后使用DefaultServeMux来监听某一端口: http.ListenAndServe(":9999", nil) 在程序里面添加上面的代码后,运行时我们可以通过浏览器或wget访问下面的http地址获取CPU profile: http://localhost:9999/debug/pprof/profile?seconds=30 这个http请求会等seconds参数指定的秒数,这期间读取请求返回的二进制格式内容,我们把返回的内容保存为文件,假设取名为cpu.prof, 这个文件里面包含了程序收到请求后的seconds秒内运行占用CPU的情况。 接下来我们通过在命令行输入[`go tool pprof`](https://golang.google.cn/cmd/pprof/)来查看cpu.prof: go tool pprof cpu.prof 这个命令会进入命令行交互,我们可以输入很多子命令来查看相关信息,最常用的几个子命令是: top N 该子命令会列出最耗时的N个函数调用,在输入top命令前输入cum或flat可以使得top列出的列表按cum或flat列排序,flat是单个函数自身(不计函数里面调用的其它函数)的耗时,cum是函数从进入到退出总的耗时。 如果要看某个函数具体是在什么地方耗时,可以使用list子命令查看: list func_name_in_top_list 该命令会显示耗时的代码和行号, 如果提示找不到source信息,可以在`go tool pprof`后面指定保存在本地的被profile程序的binary文件,并且这个binary文件要和生成profile文件的程序是在同一平台下编译的。比如在本地的Windows机器上远程profile linux机器上运行的go程序时,确保本地指定的binary是linux机器上编译的: go tool pprof mybinarypath prof_file_from_remote_host go tool pprof mybinarypath https://myremotehost/debug/pprof/profile 为了更直观的看出热点函数的调用关系,我们更多的是使用svg和web子命令: svg > xxx.svg web svg命令会生成一个指定文件名的svg文件,web命令会生成一个svg文件并用浏览器打开这个文件,执行web命令前先确保安装了graphviz(brew install graphviz, 然后brew list graphviz查看安装位置并将安装位置的bin目录加到PATH),并确保svg文件的默认打开程序是浏览器。 通过web子命令在浏览器打开的这个svg文件非常有用, 可以清楚的看到耗时函数的调用关系图。 上面是通过浏览器或wget获取cpu.prof文件,然后使用[`go tool pprof`](https://golang.google.cn/cmd/pprof/)命令来分析这个文件,更直接的方式是直接在命令行输入: go tool pprof http://localhost:9999/debug/pprof/profile?seconds=30 这个命令会等seconds指定的秒数,这期间读取请求返回的二进制格式内容并写入临时文件,再用[`go tool pprof`](https://golang.google.cn/cmd/pprof/)查看这个文件并进入命令行交互,过程和上面保存到自定义文件是一样的。 **直接获取:** 上面通过http请求间接获取的方式实际上最终还是[`url的handler调用了runtime/pprof包的接口`](https://github.com/golang/go/blob/master/src/net/http/pprof/pprof.go#L105): import "runtime/pprof" func Profile(w http.ResponseWriter, r *http.Request) { sec, _ := strconv.ParseInt(r.FormValue("seconds"), 10, 64) if sec == 0 { sec = 30 } if durationExceedsWriteTimeout(r, float64(sec)) { w.Header().Set("Content-Type", "text/plain; charset=utf-8") w.Header().Set("X-Go-Pprof", "1") w.WriteHeader(http.StatusBadRequest) fmt.Fprintln(w, "profile duration exceeds server's WriteTimeout") return } // Set Content Type assuming StartCPUProfile will work, // because if it does it starts writing. w.Header().Set("Content-Type", "application/octet-stream") if err := pprof.StartCPUProfile(w); err != nil { // StartCPUProfile failed, so no writes yet. // Can change header back to text content // and send error code. w.Header().Set("Content-Type", "text/plain; charset=utf-8") w.Header().Set("X-Go-Pprof", "1") w.WriteHeader(http.StatusInternalServerError) fmt.Fprintf(w, "Could not enable CPU profiling: %s\n", err) return } sleep(w, time.Duration(sec)*time.Second) pprof.StopCPUProfile() } 在查看线上的服务在不同场景下,不同时间段内的运行情况时,使用上面的方式还是很方便的; 但在开发或者优化的时候,我们会改动一些代码,然后想和改动前对比下,看看性能是否有提升,这时我们就需要在代码中确定固定的开始和结束位置来profie,比如某个函数从进入到退出,或某个测试程序从启动到退出,就不能像上面那样大致在某个时间点发出http请求,然后大致等一段时间;这时我们需要在程序里面直接调用[`runtime/pprof`](https://golang.google.cn/pkg/runtime/pprof/)包的接口: import "runtime/pprof" var cpuprofile = flag.String("cpuprofile", "", "write cpu profile `file`") func main() { flag.Parse() if *cpuprofile != "" { f, err := os.Create(*cpuprofile) if err != nil { log.Fatal("could not create CPU profile: ", err) } if err := pprof.StartCPUProfile(f); err != nil { log.Fatal("could not start CPU profile: ", err) } defer pprof.StopCPUProfile() } // ... rest of the program ... } 上面的代码cup profile的周期是从程序启动到退出,profile的内容保存到cpuprofile参数指定的文件,和前面通过http请求获取的cpu.prof一样,我们通过[`go tool pprof`](https://golang.google.cn/cmd/pprof/)来查看这个文件。 除了像上面那样在程序中加profile的代码,`go test`命令自带profile功能,可以在运行`go test`命令时指定[`profile相关的flag`](https://golang.google.cn/cmd/go/#hdr-Description_of_testing_flags),例如下面的命令运行当前目录下的测试用例并将cpu和heap profile写到指定的文件,然后我们就可以用[`go tool pprof`](https://golang.google.cn/cmd/pprof/)来查看这些profile文件了: go test -cpuprofile cpu.prof -memprofile mem.prof -bench . #### 3. **程序当前的内存使用情况** **用处:** 查看当前内存占用,是否有未及时释放的内存,例如不断增长的slice或map;查看内存分配历史统计,是否有对象分配过于频繁,能否复用分配的对象。 **通过http请求间接获取:** 同第1点里面获取goroutine信息一样,在程序中引入包[`net/http/pprof`](https://golang.google.cn/pkg/net/http/pprof/)并只使用它的初始化: import _ "net/http/pprof" 然后使用DefaultServeMux来监听某一端口: http.ListenAndServe(":9999", nil) 在程序里面添加上面的代码后,运行时我们可以通过浏览器或wget访问下面的http地址获取heap profile: http://localhost:9999/debug/pprof/heap 这个http请求会立刻返回二进制格式的内容,我们把返回的内容保存为文件,假设取名为mem.prof, 这个文件里面包含了程序当前正在使用的内存的占用情况。 接下来我们通过在命令行输入[`go tool pprof`](https://golang.google.cn/cmd/pprof/)来查看mem.prof: go tool pprof mem.prof 这一句是查看分配之后还没有释放的内存(in-use memory):要么正在使用,要么确实没有及时释放;这对于检查内存泄漏很有帮助。 我们还可以在上面的命令加入几个选项: -inuse_space Display in-use memory size, default -inuse_objects Display in-use object counts -alloc_space Display allocated memory size -alloc_objects Display allocated object counts 不加上面任何选项时默认是使用`-inuse_space`, 如果我们想看程序从启动到现在所有分配过的内存(包含已经被释放了的),可以指定`-alloc_space`: go tool pprof -alloc_space mem.prof 通过这个命令我们可以查看分配历史的统计,知道什么地方分配内存过于频繁,是否可以复用。 上面的这些命令会进入命令行交互,我们可以输入很多子命令来查看相关信息,最常用的几个子命令是: top N 该子命令会列出N处分配内存最多的代码所在的函数,在输入top命令前输入cum或flat可以使得top列出的列表按cum或flat列排序,flat是单个函数自身(不计函数里面调用的其它函数)的内存占用,cum是函数总的占用。 如果要看某个函数具体是在什么地方分配的内存,可以使用list子命令查看: list func_name_in_top_list 该命令会显示分配内存的代码和行号。 为了更直观的看出热点函数的调用关系,我们更多的是使用web子命令: web 该命令会生成一个svg文件并用浏览器打开这个文件 上面是通过浏览器或wget获取mem.prof文件,然后使用[`go tool pprof`](https://golang.google.cn/cmd/pprof/)命令来查看这个文件,更直接的方式是直接在命令行输入: go tool pprof http://localhost:9999/debug/pprof/heap 这个命令会将http的返回写入临时文件,再用[`go tool pprof`](https://golang.google.cn/cmd/pprof/)查看这个文件并进入命令行交互,过程和上面保存到自定义文件是一样的。 **直接获取:** import "runtime/pprof" ... f, err := os.Create(*memprofile) if err != nil { log.Fatal("could not create memory profile: ", err) } runtime.GC() // get up-to-date statistics if err := pprof.WriteHeapProfile(f); err != nil { log.Fatal("could not write memory profile: ", err) } f.Close() 上面的代码可以在程序的任何地方执行,输出的文件的内容就是程序当前的内存使用情况, 和前面通过http请求获取的mem.prof一样,我们通过[`go tool pprof`](https://golang.google.cn/cmd/pprof/)来查看这个文件。 #### 4. **一段时间内所有goroutine的调度和执行过程** **用处:** 前面的3点对于保证程序正常工作很有用,但是如果我们想提高程序的性能,例如在网络IO或数据库IO很大的情况下如何充分利用CPU来提高处理速度,这时前面3点就不够用了。我们需要了解各个goroutine是如何被调度的,如何同步执行的;网络等待,同步锁等待,还有系统调用的等待都发生在什么地方,在这些等待的地方是不是有CPU空闲被浪费了,这些信息都在trace里面。 **通过http请求间接获取:** 同第1点里面获取goroutine信息一样,在程序中引入包[`net/http/pprof`](https://golang.google.cn/pkg/net/http/pprof/)并只使用它的初始化: import _ "net/http/pprof" 然后使用DefaultServeMux来监听某一端口: http.ListenAndServe(":9999", nil) 在程序里面添加上面的代码后,运行时我们可以通过浏览器或wget访问下面的http地址获取trace信息: http://localhost:9999/debug/pprof/trace?seconds=10 这个http请求会等待seconds秒,这期间读取请求返回的二进制格式内容,我们把返回的内容保存为文件,假设取名为trace.out, 这个文件里面包含了这段时间内的trace信息。 接下来我们通过在命令行输入[`go tool trace`](https://golang.google.cn/cmd/trace/)来查看trace.out: go tool trace trace.out 这个命令会开启一个web服务,然后打开浏览器运行一个web app,显示有如下title: View trace Goroutine analysis Network blocking profile Synchronization blocking profile Syscall blocking profile Scheduler latency profile 点击各个title都可以进入查看详细信息,其中"View trace"是一个UI交互界面,可以按时间轴查看各个goroutine在各个OS thread上的执行顺序,关于这个web app的详细使用方式可以参考[`这篇文章`](https://blog.gopheracademy.com/advent-2017/go-execution-tracer/)。 **直接获取:** 上面通过http请求间接获取的方式实际上最终是[`url的handler调用了runtime/trace包的接口`](https://github.com/golang/go/blob/master/src/net/http/pprof/pprof.go#L139): import "runtime/trace" func Trace(w http.ResponseWriter, r *http.Request) { sec, err := strconv.ParseFloat(r.FormValue("seconds"), 64) if sec <= 0 || err != nil { sec = 1 } if durationExceedsWriteTimeout(r, sec) { w.Header().Set("Content-Type", "text/plain; charset=utf-8") w.Header().Set("X-Go-Pprof", "1") w.WriteHeader(http.StatusBadRequest) fmt.Fprintln(w, "profile duration exceeds server's WriteTimeout") return } // Set Content Type assuming trace.Start will work, // because if it does it starts writing. w.Header().Set("Content-Type", "application/octet-stream") if err := trace.Start(w); err != nil { // trace.Start failed, so no writes yet. // Can change header back to text content and send error code. w.Header().Set("Content-Type", "text/plain; charset=utf-8") w.Header().Set("X-Go-Pprof", "1") w.WriteHeader(http.StatusInternalServerError) fmt.Fprintf(w, "Could not enable tracing: %s\n", err) return } sleep(w, time.Duration(sec*float64(time.Second))) trace.Stop() } 我们可以在程序里面直接调用[`runtime/trace`](https://golang.google.cn/pkg/runtime/trace/)包的接口: import "runtime/trace" var traceprofile = flag.String("traceprofile", "", "write trace profile `file`") func main() { flag.Parse() if *traceprofile != "" { f, err := os.Create(*traceprofile) if err != nil { log.Fatal("could not create trace profile: ", err) } if err := trace.Start(f); err != nil { log.Fatal("could not start trace profile: ", err) } defer trace.Stop() } // ... rest of the program ... } 上面的代码trace profile的周期是从程序启动到退出,profile的内容保存到traceprofile参数指定的文件,和前面通过http请求获取的trace.out一样,我们通过[`go tool trace`](https://golang.google.cn/cmd/trace/)来查看这个文件。 #### **另外可参考下面的文章做深入了解:** [golang 内存分析/动态追踪](https://lrita.github.io/2017/05/26/golang-memory-pprof/) [Profiling Go programs with pprof](https://jvns.ca/blog/2017/09/24/profiling-go-with-pprof/) [Custom pprof profiles](https://rakyll.org/custom-profiles/) [Mutex profile](https://rakyll.org/mutexprofile/) [pprof user interface](https://rakyll.org/pprof-ui/) [Go execution tracer](https://blog.gopheracademy.com/advent-2017/go-execution-tracer/) [go tool trace](https://making.pusher.com/go-tool-trace/) [An Introduction to go tool trace ](https://about.sourcegraph.com/go/an-introduction-to-go-tool-trace-rhys-hiltner/) [Go Execution Tracer(design doc)](https://docs.google.com/document/d/1FP5apqzBgr7ahCCgFO-yoVhk4YZrNIDNf9RybngBc14/edit#heading=h.ayzntospglb3) [Go, the unwritten parts](https://rakyll.org/archive/)

有疑问加站长微信联系(非本文作者))

入群交流(和以上内容无关):加入Go大咖交流群,或添加微信:liuxiaoyan-s 备注:入群;或加QQ群:692541889

10867 次点击  
加入收藏 微博
暂无回复
添加一条新回复 (您需要 登录 后才能回复 没有账号 ?)
  • 请尽量让自己的回复能够对别人有帮助
  • 支持 Markdown 格式, **粗体**、~~删除线~~、`单行代码`
  • 支持 @ 本站用户;支持表情(输入 : 提示),见 Emoji cheat sheet
  • 图片支持拖拽、截图粘贴等方式上传