Go PProf Intro

发表于 分类于 阅读次数： 本文字数： 8.7k 阅读时长 ≈ 8 分钟

Go Profling - 剖析

Using “pprof” to profiling your program
Go语言可视化性能分析工具,PProf以profile.proto读取分析样本集合，并生成报告可视化帮助分析数据(支持文本和图形报告)

  • 使用场景

    • runtime/pprof: 采集程序指定区块的运行数据分析
    • net/http/pprof: 基于HTTP Server运行,采集运行时数据分析
    • go test: 通过运行测试用例，指定所需标识进行采样

  • 安装可视化工具graphviz查看profile

    1
    2
    # Mac: $ brew install graphviz
    # Linux: $ sudo apt install graphviz

  • 支持模式

    • 报告生成 Report generation
    • 交互终端使用 Interactive terminal use
    • Web页面 Web interface

  • 可以做那些

    • CPU Profiling: CPU分析
      • 按照一定频率采集监听应用程序CPU使用情况，确定应用程序的主动消耗CPU周期时花费时间的位置
    • Memory Profiling: 内存分析
      • 程序进行堆分配时记录堆栈跟踪，监视当前和历史内存使用情况，检查内存泄漏
    • Block Profiling: 阻塞分析
      • 记录Goroutine阻塞等待同步的位置，默认不开启，需要调用runtime.SetBlockProfileRate 设置
    • Mutex Profiling: 互斥锁分析
      • 报告互斥锁的竞争情况, 默认不开启, runtime.SetMutexProfileFraction 设置
    • Goroutine Profiling: Goroutine分析
      • 对当前应用程序正在运行的Goroutine进行堆栈跟踪和分析

How to Use

  • runtime/pprof
    1
    2
    3
    4
    5
    6
    # pprof useful command:
      text: show the cpu report in text form
      web: visualize graph through web browser
      top <n>: list the n highest entries in text form
      list <function name>: reveal the running time of function
      traces
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
package main

import (
	"log"
	"net/http"
	_ "net/http/pprof"
	"time"
)

var datas []string

func main() {
	go func() {
		for {
			log.Printf("len: %d", Add("go-programming-tour-book"))
			time.Sleep(time.Millisecond * 10)
		}
	}()

	_ = http.ListenAndServe(":8080", nil)
}

func Add(str string) int {
	data := []byte(str)
	datas = append(datas, string(data))
	return len(datas)
}

// 访问 http://localhost:8080/debug/pprof
// /debug/pprof/
//
// Types of profiles available:
// Count	Profile
// 3	allocs                -- 查看过去内存分配样本
// 0	block                 -- 查看阻塞
// 0	cmdline               -- 命令行调用路径
// 5	goroutine             -- goroutine堆栈跟踪
// 3	heap                  -- 堆上内存分配
// 0	mutex                 -- 互斥锁竞争持有者堆栈跟踪
// 0	profile               -- 默认30秒CPU Profiling
// 7	threadcreate          --
// 0	trace
// full goroutine stack dump

  • CPU Profiling

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    22
    23
    24
    25
    26
    27
    28
    ➜ go tool pprof http://localhost:8080/debug/pprof/profile\?seconds\=5
    Fetching profile over HTTP from http://localhost:8080/debug/pprof/profile?seconds=5
    Saved profile in /Users/chyiyaqing/pprof/pprof.samples.cpu.001.pb.gz
    Type: cpu
    Time: Sep 13, 2021 at 5:22pm (CST)
    Duration: 5s, Total samples = 20ms (  0.4%)
    Entering interactive mode (type "help" for commands, "o" for options)
    (pprof) top10
    Showing nodes accounting for 20ms, 100% of 20ms total
    Showing top 10 nodes out of 11
          flat  flat%   sum%        cum   cum%
          10ms 50.00% 50.00%       10ms 50.00%  runtime.kevent
          10ms 50.00%   100%       10ms 50.00%  runtime.pthread_cond_wait
             0     0%   100%       20ms   100%  runtime.findrunnable
             0     0%   100%       10ms 50.00%  runtime.mPark
             0     0%   100%       20ms   100%  runtime.mcall
             0     0%   100%       10ms 50.00%  runtime.netpoll
             0     0%   100%       10ms 50.00%  runtime.notesleep
             0     0%   100%       20ms   100%  runtime.park_m
             0     0%   100%       20ms   100%  runtime.schedule
             0     0%   100%       10ms 50.00%  runtime.semasleep

    flat: 函数自身运行耗时
    flat%: 函数自身在CPU运行耗时总比例
    sum%: 函数自身累计使用CPU比例
    cum%: 函数自身及其调用函数运行总耗时
    cum%: 函数自身及其调用函数的运行耗时总比例
    Name: 函数名

  • Heap Profiling

    • inuse_space: 分析常驻内存占用
      1
      2
      3
      4
      5
      6
      7
      8
      9
      10
      11
      12
      13
      14
      15
      16
      17
      18
      19
      20
      21
      22
      23
      24
      25
      26
      27
      28
      29
      30
      31
      32
      33
      34
      35
      36
      37
      38
      39
      40
      ➜ go tool pprof -inuse_space http://localhost:8080/debug/pprof/heap
      Fetching profile over HTTP from http://localhost:8080/debug/pprof/heap
      Saved profile in /Users/chyiyaqing/pprof/pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.002.pb.gz
      Type: inuse_space
      Time: Sep 13, 2021 at 5:30pm (CST)
      Entering interactive mode (type "help" for commands, "o" for options)
      (pprof) top
      Showing nodes accounting for 6951.53kB, 100% of 6951.53kB total
      Showing top 10 nodes out of 18
            flat  flat%   sum%        cum   cum%
       4898.20kB 70.46% 70.46%  4898.20kB 70.46%  main.Add (inline)
       1025.12kB 14.75% 85.21%  1025.12kB 14.75%  runtime.allocm
        516.01kB  7.42% 92.63%   516.01kB  7.42%  unicode.init
        512.20kB  7.37%   100%   512.20kB  7.37%  runtime.malg
               0     0%   100%  4898.20kB 70.46%  main.main.func1
               0     0%   100%   516.01kB  7.42%  runtime.doInit
               0     0%   100%   516.01kB  7.42%  runtime.main
               0     0%   100%  1025.12kB 14.75%  runtime.mstart
               0     0%   100%  1025.12kB 14.75%  runtime.mstart0
               0     0%   100%  1025.12kB 14.75%  runtime.mstart1
      (pprof) traces
      Type: alloc_objects
      Time: Sep 13, 2021 at 5:57pm (CST)
      -----------+-------------------------------------------------------
           bytes:  256kB
               2   compress/flate.(*compressor).init
                   compress/flate.NewWriter
                   compress/gzip.(*Writer).Write
                   runtime/pprof.(*profileBuilder).build
                   runtime/pprof.printCountProfile
                   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
      -----------+-------------------------------------------------------
    • alloc_space: 分析分配内存空间大小
    • alloc_objects:
    • inuse_objects:

  • Goroutine Profiling

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    22
    23
    24
    25
    26
    27
    28
    29
    30
    31
    32
    33
    34
    35
    36
    37
    38
    39
    40
    41
    42
    43
    44
    45
    46
    47
    48
    49
    50
    ➜ go tool pprof http://localhost:8080/debug/pprof/goroutine
    Fetching profile over HTTP from http://localhost:8080/debug/pprof/goroutine
    Saved profile in /Users/chyiyaqing/pprof/pprof.goroutine.001.pb.gz
    Type: goroutine
    Time: Sep 13, 2021 at 5:54pm (CST)
    Entering interactive mode (type "help" for commands, "o" for options)
    (pprof) traces  // 打印调用栈
    Type: goroutine
    Time: Sep 13, 2021 at 5:54pm (CST)
    -----------+-------------------------------------------------------
             1   runtime.gopark
                 runtime.netpollblock
                 internal/poll.runtime_pollWait
                 internal/poll.(*pollDesc).wait
                 internal/poll.(*pollDesc).waitRead (inline)
                 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.(*pollDesc).waitRead (inline)
                 internal/poll.(*FD).Accept
                 net.(*netFD).accept
                 net.(*TCPListener).accept
                 net.(*TCPListener).Accept
                 net/http.(*Server).Serve
                 net/http.(*Server).ListenAndServe
                 net/http.ListenAndServe (inline)
                 main.main
                 runtime.main
    -----------+-------------------------------------------------------
             1   runtime.gopark
                 time.Sleep
                 main.main.func1
    -----------+-------------------------------------------------------
             1   runtime/pprof.runtime_goroutineProfileWithLabels
                 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
    -----------+-------------------------------------------------------

  • Mutex Profiling

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    22
    23
    24
    25
    ➜ go tool pprof http://localhost:8080/debug/pprof/mutex
    Fetching profile over HTTP from http://localhost:8080/debug/pprof/mutex
    Saved profile in /Users/chyiyaqing/pprof/pprof.contentions.delay.003.pb.gz
    Type: delay
    Time: Sep 13, 2021 at 6:05pm (CST)
    Entering interactive mode (type "help" for commands, "o" for options)
    (pprof) top
    Showing nodes accounting for 941.98us, 100% of 941.98us total
          flat  flat%   sum%        cum   cum%
      941.98us   100%   100%   941.98us   100%  sync.(*Mutex).Unlock
             0     0%   100%   941.98us   100%  main.main.func1
    (pprof) list main
    Total: 941.98us
    ROUTINE ======================== main.main.func1 in /Users/chyiyaqing/Downloads/pprof/pprof/main2.go
             0   941.98us (flat, cum)   100% of Total
             .          .     18:	for i := 0; i < 999; i++ {
             .          .     19:		go func(i int) {
             .          .     20:			m.Lock()
             .          .     21:			defer m.Unlock()
             .          .     22:			datas[i] = struct{}{}
             .   941.98us     23:		}(i)
             .          .     24:	}
             .          .     25:
             .          .     26:	_ = http.ListenAndServe(":8080", nil)
             .          .     27:}

  • Block Profiling

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    22
    23
    24
    25
    26
    27
    28
    29
    ➜ go tool pprof http://localhost:8080/debug/pprof/block
    Fetching profile over HTTP from http://localhost:8080/debug/pprof/block
    Saved profile in /Users/chyiyaqing/pprof/pprof.contentions.delay.005.pb.gz
    Type: delay
    Time: Sep 13, 2021 at 6:17pm (CST)
    Entering interactive mode (type "help" for commands, "o" for options)
    (pprof) top
    Showing nodes accounting for 92.66ms, 100% of 92.67ms total
    Dropped 4 nodes (cum <= 0.46ms)
          flat  flat%   sum%        cum   cum%
       92.66ms   100%   100%    92.66ms   100%  sync.(*Mutex).Lock (inline)
             0     0%   100%    92.66ms   100%  main.main.func1
    (pprof) list
    command list requires an argument
    (pprof) list main
    Total: 92.67ms
    ROUTINE ======================== main.main.func1 in /Users/chyiyaqing/Downloads/pprof/pprof/main2.go
             0    92.66ms (flat, cum)   100% of Total
             .          .     17:func main() {
             .          .     18:	var m sync.Mutex
             .          .     19:	var datas = make(map[int]struct{})
             .          .     20:	for i := 0; i < 999; i++ {
             .          .     21:		go func(i int) {
             .    92.66ms     22:			m.Lock()
             .          .     23:			defer m.Unlock()
             .          .     24:			datas[i] = struct{}{}
             .          .     25:		}(i)
             .          .     26:	}
             .          .     27:

  • 查看可视化界面

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    22
    23
    24
    25
    26
    27
    ➜ wget http://127.0.0.1:8080/debug/pprof/profile
    --2021-09-13 18:25:42--  http://127.0.0.1:8080/debug/pprof/profile
    Connecting to 127.0.0.1:8080... connected.
    HTTP request sent, awaiting response... 200 OK
    Length: 1290 (1.3K) [application/octet-stream]
    Saving to: ‘profile’

    profile                            100%[================================================================>]   1.26K  --.-KB/s    in 0s

    2021-09-13 18:26:12 (205 MB/s) - ‘profile’ saved [1290/1290]

    # 方法一
    ➜ go tool pprof -http=:6001 profile
    Serving web UI on http://localhost:6001
      # Top
      # Graph: 函数调用流程
      # Peek: 上下文信息
      # Source: 源代码的追踪和分析
      # Flame Graph:

    # 方法二
    ➜ go tool pprof profile
    Type: cpu
    Time: Sep 13, 2021 at 6:25pm (CST)
    Duration: 30s, Total samples = 240ms (  0.8%)
    Entering interactive mode (type "help" for commands, "o" for options)
    (pprof) web