go tool pprof与trace的简单使用

pprof

pprof是Google的程序采样分析工具,其使用分为,采样和分析。Go 语言内置了pprof。
Go 语言库中有两种方式使用pprof,一种是通过net/http/pprof库,另一种是通过runtime/pprof库。

net/http/pprof的简单使用

引入 _ "net/http/pprof"库,开启http://localhost:6060端口的服务,注意其ListenAndServeaddr是可以指定的,handler参数为nil。

package main

import (
	"math/rand"
	"net/http"
	_ "net/http/pprof"
	"runtime"
	"sync"
	"time"
)

func main() {
	runtime.SetMutexProfileFraction(1) // 开启对锁调用的跟踪
	runtime.SetBlockProfileRate(1)     // 开启对阻塞的跟踪

	go func() {
		if err := http.ListenAndServe(":6060", nil); err != nil {
			panic(err)
		}
	}()

	wg := new(sync.WaitGroup)
	randFunction(wg)
	wg.Wait()
}

func randFunction(wg *sync.WaitGroup) {
	rand.Seed(time.Now().UnixNano())
	for i := 0; i < 100; i++ {
		wg.Add(1)
		go func() {
			defer wg.Done()
			s := make([]int, rand.Intn(100000))
			time.Sleep(time.Second * time.Duration(rand.Intn(999999)))
			_ = s
		}()
	}
}

启动程序后,打开浏览器输入:http://localhost:6060/debug/pprof/。可见如下页面:
在这里插入图片描述
配置文件说明:
allocs(分配): 所有过去内存分配的样本
block(阻塞):导致同步基元阻塞的堆栈跟踪
cmdline(命令行程序):当前程序的命令行调用
goroutine(协程信息):当前所有 goroutines 的堆栈跟踪
heap(堆信息):活动对象的内存分配采样。您可以指定 gc GET 参数以在获取堆示例之前运行 GC
mutex(锁信息):争用互斥锁持有者的堆栈跟踪
profile(配置信息):CPU 配置文件。您可以在秒 GET 参数中指定持续时间。获取配置文件后,使用 go 工具 pprof 命令调查配置文件。
threadcreate(线程创建):导致创建新的操作系统线的程堆栈跟踪
trace(跟踪):当前程序执行的跟踪。您可以在秒 GET 参数中指定持续时间。获取跟踪文件后,使用 go 工具跟踪命令调查跟踪
full goroutine stack dump:dump 所有协程的栈信息
蓝色文字前的数字描述了该操作的“具体数量”
蓝色超链接是可以点击的,比如点击:goroutine
跳转到了http://localhost:6060/debug/pprof/goroutine?debug=1链接,这里展示了goroutine的跟踪信息。
在这里插入图片描述
http://localhost:6060/debug/pprof/goroutine?debug=1中结尾的?debug=1去掉,即可下载当前goroutine的跟踪信息到文件,可用具体的分析工具对其进行分析。

go tool pprof 分析工具

-h 选项可以查看帮助信息。
该工具可以静态分析数据文件,也可以动态的网络流分析。
可以看出pprof <format> [options] [binary] <source> ... pprof 其后可跟一个source,这个source可以是从浏览器下载(curl 也可以获取,或使用runtime/pprof生成)的数据问文件,也可以是一个链接

...\example>go tool pprof -h                                       
usage:
                                                                         
Produce output in the specified format.                                  
                                                                         
   pprof <format> [options] [binary] <source> ...

Omit the format to get an interactive shell whose commands can be used   
to generate various views of a profile

   pprof [options] [binary] <source> ...
                                                                         
Omit the format and provide the "-http" flag to get an interactive web   
interface at the specified host:port that can be used to navigate through
various views of a profile.                                              

   pprof -http [host]:[port] [options] [binary] <source> ...

Details:
  Output formats (select at most one):
    -callgrind       Outputs a graph in callgrind format
    -comments        Output all profile comments
    -disasm          Output assembly listings annotated with samples
    -dot             Outputs a graph in DOT format
    -eog             Visualize graph through eog
    -evince          Visualize graph through evince
    -gif             Outputs a graph image in GIF format
    -gv              Visualize graph through gv
    -kcachegrind     Visualize report in KCachegrind
    -list            Output annotated source for functions matching regexp
    -pdf             Outputs a graph in PDF format
    -peek            Output callers/callees of functions matching regexp
    -png             Outputs a graph image in PNG format
    -proto           Outputs the profile in compressed protobuf format
    -ps              Outputs a graph in PS format
    -raw             Outputs a text representation of the raw profile
    -svg             Outputs a graph in SVG format
    -tags            Outputs all tags in the profile
    -text            Outputs top entries in text form
    -top             Outputs top entries in text form
    -topproto        Outputs top entries in compressed protobuf format
    -traces          Outputs all profile samples in text form
    -tree            Outputs a text rendering of call graph
    -web             Visualize graph through web browser
    -weblist         Display annotated source in a web browser

  Options:
    -call_tree       Create a context-sensitive call tree
    -compact_labels  Show minimal headers
    -divide_by       Ratio to divide all samples before visualization
    -drop_negative   Ignore negative differences
    -edgefraction    Hide edges below <f>*total
    -focus           Restricts to samples going through a node matching regexp
    -hide            Skips nodes matching regexp
    -ignore          Skips paths going through any nodes matching regexp
    -intel_syntax    Show assembly in Intel syntax
    -mean            Average sample value over first value (count)
    -nodecount       Max number of nodes to show
    -nodefraction    Hide nodes below <f>*total
    -noinlines       Ignore inlines.
    -normalize       Scales profile based on the base profile.
    -output          Output filename for file-based outputs
    -prune_from      Drops any functions below the matched frame.
    -relative_percentages Show percentages relative to focused subgraph
    -sample_index    Sample value to report (0-based index or name)
    -show            Only show nodes matching regexp
    -show_from       Drops functions above the highest matched frame.
    -source_path     Search path for source files
    -tagfocus        Restricts to samples with tags in range or matched by regexp
    -taghide         Skip tags matching this regexp
    -tagignore       Discard samples with tags in range or matched by regexp
    -tagleaf         Adds pseudo stack frames for labels key/value pairs at the callstack leaf.
    -tagroot         Adds pseudo stack frames for labels key/value pairs at the callstack root.
    -tagshow         Only consider tags matching this regexp
    -trim            Honor nodefraction/edgefraction/nodecount defaults
    -trim_path       Path to trim from source paths before search
    -unit            Measurement units to display

  Option groups (only set one per group):
    granularity
      -functions       Aggregate at the function level.
      -filefunctions   Aggregate at the function level.
      -files           Aggregate at the file level.
      -lines           Aggregate at the source code line level.
      -addresses       Aggregate at the address level.
    sort
      -cum             Sort entries based on cumulative weight
      -flat            Sort entries based on own weight

  Source options:
    -seconds              Duration for time-based profile collection
    -timeout              Timeout in seconds for profile collection
    -buildid              Override build id for main binary
    -add_comment          Free-form annotation to add to the profile
                          Displayed on some reports or with pprof -comments
    -diff_base source     Source of base profile for comparison
    -base source          Source of base profile for profile subtraction
    profile.pb.gz         Profile in compressed protobuf format
    legacy_profile        Profile in legacy pprof format
    http://host/profile   URL for profile handler to retrieve
    -symbolize=           Controls source of symbol information
      none                  Do not attempt symbolization
      local                 Examine only local binaries
      fastlocal             Only get function names from local binaries
      remote                Do not examine local binaries
      force                 Force re-symbolization
    Binary                  Local path or build id of binary for symbolization
    -tls_cert             TLS client certificate file for fetching profile and symbols
    -tls_key              TLS private key file for fetching profile and symbols
    -tls_ca               TLS CA certs file for fetching profile and symbols

  Misc options:
   -http              Provide web interface at host:port.
                      Host is optional and 'localhost' by default.
                      Port is optional and a randomly available port by default.
   -no_browser        Skip opening a browser for the interactive web UI.
   -tools             Search path for object tools

  Legacy convenience options:
   -inuse_space           Same as -sample_index=inuse_space
   -inuse_objects         Same as -sample_index=inuse_objects
   -alloc_space           Same as -sample_index=alloc_space
   -alloc_objects         Same as -sample_index=alloc_objects
   -total_delay           Same as -sample_index=delay
   -contentions           Same as -sample_index=contentions
   -mean_delay            Same as -mean -sample_index=delay

  Environment Variables:
   PPROF_TMPDIR       Location for saved profiles (default $HOME/pprof)
   PPROF_TOOLS        Search path for object-level tools
   PPROF_BINARY_PATH  Search path for local binary files
                      default: $HOME/pprof/binaries
                      searches $name, $path, $buildid/$name, $path/$buildid
   * On Windows, %USERPROFILE% is used instead of $HOME

使用go tool pprof http://localhost:6060/debug/pprof/allocs分析当前应用内存信息。

...\Desktop\example>go tool pprof http://localhost:6060/debug/pprof/allocs   
Fetching profile over HTTP from http://localhost:6060/debug/pprof/allocs
Saved profile in 
...\pprof\pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.002.pb.gz
Type: alloc_space
Time: Jan 22, 2023 at 4:28pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)

可以发现,该命令行是交互式的。
输入help 可以查看其支持的所有子命令。

(pprof) help
  Commands:
    callgrind        Outputs a graph in callgrind format
    comments         Output all profile comments
    disasm           Output assembly listings annotated with samples
    dot              Outputs a graph in DOT format
    eog              Visualize graph through eog
    evince           Visualize graph through evince
    gif              Outputs a graph image in GIF format
    gv               Visualize graph through gv
    kcachegrind      Visualize report in KCachegrind
    list             Output annotated source for functions matching regexp
    pdf              Outputs a graph in PDF format
    peek             Output callers/callees of functions matching regexp
    png              Outputs a graph image in PNG format
    proto            Outputs the profile in compressed protobuf format
    ps               Outputs a graph in PS format
    raw              Outputs a text representation of the raw profile
    svg              Outputs a graph in SVG format
    tags             Outputs all tags in the profile
    text             Outputs top entries in text form
    top              Outputs top entries in text form
    topproto         Outputs top entries in compressed protobuf format
    traces           Outputs all profile samples in text form
    tree             Outputs a text rendering of call graph
    web              Visualize graph through web browser
    weblist          Display annotated source in a web browser
    o/options        List options and their current values
    q/quit/exit/^D   Exit pprof

  Options:
    call_tree        Create a context-sensitive call tree
    compact_labels   Show minimal headers
    divide_by        Ratio to divide all samples before visualization
    drop_negative    Ignore negative differences
    edgefraction     Hide edges below <f>*total
    focus            Restricts to samples going through a node matching regexp
    hide             Skips nodes matching regexp
    ignore           Skips paths going through any nodes matching regexp
    intel_syntax     Show assembly in Intel syntax
    mean             Average sample value over first value (count)
    nodecount        Max number of nodes to show
    nodefraction     Hide nodes below <f>*total
    noinlines        Ignore inlines.
    normalize        Scales profile based on the base profile.
    output           Output filename for file-based outputs
    prune_from       Drops any functions below the matched frame.
    relative_percentages Show percentages relative to focused subgraph
    sample_index     Sample value to report (0-based index or name)
    show             Only show nodes matching regexp
    show_from        Drops functions above the highest matched frame.
    source_path      Search path for source files
    tagfocus         Restricts to samples with tags in range or matched by regexp
    taghide          Skip tags matching this regexp
    tagignore        Discard samples with tags in range or matched by regexp
    tagleaf          Adds pseudo stack frames for labels key/value pairs at the callstack leaf.
    tagroot          Adds pseudo stack frames for labels key/value pairs at the callstack root.
    tagshow          Only consider tags matching this regexp
    trim             Honor nodefraction/edgefraction/nodecount defaults
    trim_path        Path to trim from source paths before search
    unit             Measurement units to display

  Option groups (only set one per group):
    granularity
      functions        Aggregate at the function level.
      filefunctions    Aggregate at the function level.
      files            Aggregate at the file level.
      lines            Aggregate at the source code line level.
      addresses        Aggregate at the address level.
    sort
      cum              Sort entries based on cumulative weight
      flat             Sort entries based on own weight
  :   Clear focus/ignore/hide/tagfocus/tagignore

  type "help <cmd|option>" for more information
(pprof)

使用top,就可以查看所有内存占用信息

(pprof) top
Showing nodes accounting for 46504.27kB, 100% of 46504.27kB total
Showing top 10 nodes out of 34
      flat  flat%   sum%        cum   cum%
42900.35kB 92.25% 92.25% 42900.35kB 92.25%  main.randFunction.func1
  902.59kB  1.94% 94.19%  1553.21kB  3.34%  compress/flate.NewWriter
  650.62kB  1.40% 95.59%   650.62kB  1.40%  compress/flate.(*compressor).init
     514kB  1.11% 96.70%      514kB  1.11%  bufio.NewWriterSize (inline)
  512.50kB  1.10% 97.80%   512.50kB  1.10%  runtime.allocm
  512.20kB  1.10% 98.90%   512.20kB  1.10%  runtime.malg
  512.01kB  1.10%   100%   512.01kB  1.10%  runtime/pprof.printCountProfile.func1
         0     0%   100%  1553.21kB  3.34%  compress/gzip.(*Writer).Write
         0     0%   100%  2065.22kB  4.44%  net/http.(*ServeMux).ServeHTTP
         0     0%   100%  2579.22kB  5.55%  net/http.(*conn).serve
(pprof)

输入top n(1个有效的数字),可以查看前n项内存分配信息

(pprof) top 3
Showing nodes accounting for 44453.56kB, 95.59% of 46504.27kB total
Showing top 3 nodes out of 34
      flat  flat%   sum%        cum   cum%
42900.35kB 92.25% 92.25% 42900.35kB 92.25%  main.randFunction.func1
  902.59kB  1.94% 94.19%  1553.21kB  3.34%  compress/flate.NewWriter
  650.62kB  1.40% 95.59%   650.62kB  1.40%  compress/flate.(*compressor).init
(pprof)

可见,上边的信息最后一列是具体的包名.函数名
使用 list 包名.函数名 可以查看该函数具体内存分配信息

(pprof) list main.randFunction.func1
Total: 45.41MB
ROUTINE ======================== main.randFunction.func1 in 
...\example\main\main.go
   41.89MB    41.89MB (flat, cum) 92.25% of Total
         .          .     28:   rand.Seed(time.Now().UnixNano())
         .          .     29:   for i := 0; i < 100; i++ {
         .          .     30:           wg.Add(1)
         .          .     31:           go func() {
         .          .     32:                   defer wg.Done()
   41.89MB    41.89MB     33:                   s := make([]int, rand.Intn(100000))
         .          .     34:                   time.Sleep(time.Second * time.Duration(rand.Intn(999999)))
         .          .     35:                   _ = s
         .          .     36:           }()
         .          .     37:   }
         .          .     38:}
(pprof)

可以看出导致大量内存分配的罪魁祸首是s := make([]int, rand.Intn(100000)),分配了41.89MB内存

   41.89MB    41.89MB     33:                   s := make([]int, rand.Intn(100000))

输入 web 可以在web端以图的方式展现信息

(pprof) web
failed to execute dot. Is Graphviz installed? Error: exec: "dot": executable file not found in %PATH%
(pprof) 

上边说的是让我们安装Graphviz这个工具。需把该命令加入环境变量的PATH中。
http://www.graphviz.org/该网站中Download即可。
安装时根据个人喜好,选择环境变量。
在这里插入图片描述
此时重启一次命令行,并重新输入

...\example>go tool pprof http://localhost:6060/debug/pprof/allocs
Fetching profile over HTTP from http://localhost:6060/debug/pprof/allocs
Saved profile in 
...\pprof\pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.005.pb.gz
Type: alloc_space
Time: Jan 22, 2023 at 4:46pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) web
(pprof)

便可查看具体函数内存占用。同理还可以查看其他指标的信息。
在这里插入图片描述
节点颜色:
红色:累计值cum为正,并且很大
绿色:累计值cum为负,并且很大
灰色:cum可以忽略不计
节点字体大小:
较大的字体表示当前值较大
较小的字体表示当前值较小
边框颜色:
红色:当前值较大并且为正
绿色:当前值较小并未为负
灰色:当前值接近0
箭头大小:
箭头越粗:当前路径消耗的资源越多
箭头越细:当前路径消耗的资源越少
箭头线性:
虚线:两个节点间某些节点可以被忽略,为间接调用
实现:两个节点间为直接调用

在url中可以使用second指定采样的时间:http://localhost:6060/debug/pprof/trace?seconds=5,采样时间为5秒。

使用tree命令可以查找到函数的调用链

(pprof) tree
Showing nodes accounting for 44816.50kB, 100% of 44816.50kB total
----------------------------------------------------------+-------------
      flat  flat%   sum%        cum   cum%   calls calls% + context

----------------------------------------------------------+-------------
43791.80kB 97.71% 97.71% 43791.80kB 97.71%                | main.randFunction.func1
----------------------------------------------------------+-------------
                                          512.50kB   100% |   runtime.newm
  512.50kB  1.14% 98.86%   512.50kB  1.14%                | runtime.allocm
----------------------------------------------------------+-------------
                                          512.20kB   100% |   runtime.newproc1
  512.20kB  1.14%   100%   512.20kB  1.14%                | runtime.malg
----------------------------------------------------------+-------------
         0     0%   100%   512.50kB  1.14%                | runtime.mstart
                                          512.50kB   100% |   runtime.mstart0
----------------------------------------------------------+-------------
                                          512.50kB   100% |   runtime.mstart
         0     0%   100%   512.50kB  1.14%                | runtime.mstart0
                                          512.50kB   100% |   runtime.mstart1
----------------------------------------------------------+-------------
                                          512.50kB   100% |   runtime.mstart0
         0     0%   100%   512.50kB  1.14%                | runtime.mstart1
                                          512.50kB   100% |   runtime.schedule
----------------------------------------------------------+-------------
                                          512.50kB   100% |   runtime.startm
         0     0%   100%   512.50kB  1.14%                | runtime.newm
                                          512.50kB   100% |   runtime.allocm
----------------------------------------------------------+-------------
                                          512.20kB   100% |   runtime.systemstack
         0     0%   100%   512.20kB  1.14%                | runtime.newproc.func1
                                          512.20kB   100% |   runtime.newproc1
----------------------------------------------------------+-------------
                                          512.20kB   100% |   runtime.newproc.func1
         0     0%   100%   512.20kB  1.14%                | runtime.newproc1
                                          512.20kB   100% |   runtime.malg
----------------------------------------------------------+-------------
                                          512.50kB   100% |   runtime.schedule
         0     0%   100%   512.50kB  1.14%                | runtime.resetspinning
                                          512.50kB   100% |   runtime.wakep
----------------------------------------------------------+-------------
                                          512.50kB   100% |   runtime.mstart1
         0     0%   100%   512.50kB  1.14%                | runtime.schedule
                                          512.50kB   100% |   runtime.resetspinning
----------------------------------------------------------+-------------
                                          512.50kB   100% |   runtime.wakep
         0     0%   100%   512.50kB  1.14%                | runtime.startm
                                          512.50kB   100% |   runtime.newm
----------------------------------------------------------+-------------
         0     0%   100%   512.20kB  1.14%                | runtime.systemstack
                                          512.20kB   100% |   runtime.newproc.func1
----------------------------------------------------------+-------------
                                          512.50kB   100% |   runtime.resetspinning
         0     0%   100%   512.50kB  1.14%                | runtime.wakep
                                          512.50kB   100% |   runtime.startm
----------------------------------------------------------+-------------
(pprof)

tree runtime.newm

(pprof) tree runtime.newm
Active filters:
   focus=runtime.newm
Showing nodes accounting for 512.50kB, 1.14% of 44816.50kB total
----------------------------------------------------------+-------------
      flat  flat%   sum%        cum   cum%   calls calls% + context
----------------------------------------------------------+-------------
                                          512.50kB   100% |   runtime.newm
  512.50kB  1.14%  1.14%   512.50kB  1.14%                | runtime.allocm
----------------------------------------------------------+-------------
         0     0%  1.14%   512.50kB  1.14%                | runtime.mstart
                                          512.50kB   100% |   runtime.mstart0
----------------------------------------------------------+-------------
                                          512.50kB   100% |   runtime.mstart
         0     0%  1.14%   512.50kB  1.14%                | runtime.mstart0
                                          512.50kB   100% |   runtime.mstart1
----------------------------------------------------------+-------------
                                          512.50kB   100% |   runtime.mstart0
         0     0%  1.14%   512.50kB  1.14%                | runtime.mstart1
                                          512.50kB   100% |   runtime.schedule
----------------------------------------------------------+-------------
                                          512.50kB   100% |   runtime.startm
         0     0%  1.14%   512.50kB  1.14%                | runtime.newm
                                          512.50kB   100% |   runtime.allocm
----------------------------------------------------------+-------------
                                          512.50kB   100% |   runtime.schedule
         0     0%  1.14%   512.50kB  1.14%                | runtime.resetspinning
                                          512.50kB   100% |   runtime.wakep
----------------------------------------------------------+-------------
                                          512.50kB   100% |   runtime.mstart1
         0     0%  1.14%   512.50kB  1.14%                | runtime.schedule
                                          512.50kB   100% |   runtime.resetspinning
----------------------------------------------------------+-------------
                                          512.50kB   100% |   runtime.wakep
         0     0%  1.14%   512.50kB  1.14%                | runtime.startm
                                          512.50kB   100% |   runtime.newm
----------------------------------------------------------+-------------
                                          512.50kB   100% |   runtime.resetspinning
         0     0%  1.14%   512.50kB  1.14%                | runtime.wakep
                                          512.50kB   100% |   runtime.startm
----------------------------------------------------------+-------------
(pprof)

火焰图

go tool 也内置了火焰图分析工具。
使用
go tool pprof -http :6061 http://localhost:6060/debug/pprof/profile?second=30
在收集30秒信息后会自动打开浏览器,显示火焰图。
在这里插入图片描述
在VIEW中选择Flame Graph。查看火焰图。
在这里插入图片描述
火焰图说明:
root代表程序的开始,单击每个函数可以查看具体信息。
其他框分别代表一个函数,每一层的函数都为平级的,下一层函数被上一层函数所调用。
函数调用栈越长,火焰越明亮。
框越长,颜色越深,代表该函数CPU时间占用越久。

trace 事件跟踪的简单使用

trace可以获取更加详细的调用链信息。
获取30秒trace信息:http://localhost:6060/debug/pprof/trace?second=30
通过浏览器下载该文件。
切换到文件所在路径,执行go tool trace trace最后的trace为刚刚下载的文件名。
程序自动打开了浏览器:
在这里插入图片描述
点击View trace,查看trace信息:
在这里插入图片描述

Reference
《Go 语言底层原理剖析》

评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包

打赏作者

metabit

你的鼓励将是我创作的最大动力

¥1 ¥2 ¥4 ¥6 ¥10 ¥20
扫码支付:¥1
获取中
扫码支付

您的余额不足,请更换扫码支付或充值

打赏作者

实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值