golang 调试分析方法

发表于 | 分类于 | 评论数： 0 | 阅读次数：

断点调试

Visual Studio Code

创建配置

VSCode IDE要运行或者调试golang程序之前，需要创建运行配置 launch.json ，方法如下：
vscode_config_add

打开菜单“运行”->“添加配置”，在创建的配置添加如下内容：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
{
    // 使用 IntelliSense 了解相关属性。 
    // 悬停以查看现有属性的描述。
    // 欲了解更多信息，请访问: https://go.microsoft.com/fwlink/?linkid=830387
    "version": "0.2.0",
    "configurations": [
        {
            "name": "Launch Package",
            "type": "go",
            "request": "launch",
            "mode": "auto",
            "cwd": "${workspaceFolder}",
            "program": "${workspaceFolder}/main.go",
            "args": []
        }
    ]
}

配置说明：
cwd：当前工作目录，可以使用变量 ${workspaceFolder} 。
program：可执行程序或者文件。
args：程序运行所需参数，数组类型。

更多配置的用法请参考 visualstudio debugging

调试方法

设置断点，如下图所示：
vscode_breakpoint_add

使用快捷键F5，或者打开菜单，点击“运行”->“启动调试”，调试主界面如下，这样就可以愉快的调试了。
vscode_debug_main

GoLand

创建配置

打开菜单，“Run”->“Debug”
goland_config_add

在弹出框选“Edit Configurations”
goland_config_select

编辑配置如下图所示，编辑完后点击Apply应用即可完成。
goland_debug_config

调试方法

设置断点，如下图所示
goland_breakpoint_add

启动debug，MAC快捷键control+option+D，或者点击菜单“Run”->“Debug”，选择之前创建的配置，即可调试，如下图所示：
goland_debug_main

性能分析

pprof

pprof是Go的性能分析工具，在程序运行过程中，可以记录程序的运行信息，包括CPU、内存、goroutine、锁等。golang标准库提供了以下两种使用方式：

  • net/http/pprof：采集 HTTP Server 的运行时数据进行分析
  • runtime/pprof：采集程序（含Server和非Server）的运行数据进行分析

另外，golang也提供了比较多好用的可视化工具来负责开发者做分析，使用方式包括报告的生成、交互式终端和Web界面。

pprof工具准备

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
# 安装pprof工具
go install github.com/google/pprof@latest

# 安装图形化依赖工具 Graphviz
# 以Mac为例，其他平台安装方法请参考 https://graphviz.org/download/
brew install Graphviz

# Mac平台如果安装有报错，比如
==> Pouring jasper-3.0.2.arm64_monterey.bottle.tar.gz
Error: No such file or directory @ rb_sysopen - /Users/xxx/Library/Caches/Homebrew/downloads/d3af18f496d6e7cae9775e1e69ea79074687e03221367f075c3a6e6f2c77c705--jasper-3.0.2.arm64_monterey.bottle.tar.gz

# 可以手工逐个安装报错的依赖，比如
brew install jasper
brew install gdk-pixbuf
brew install pango
brew install librsvg

分析使用

本例使用的完整 demo 放在 go-learing 的 examples/pprof 目录下。

标准库自带Web界面

使用方法

简单的demo

1
2
3
4
5
6
7
8
9
10
11
12
package main

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

func main() {
        log.Printf("pprof demo is running")
        http.ListenAndServe("0.0.0.0:8090", nil)
}

本例子使用标准库提供的 “net/http/pprof” 包，通过import该包后，HTTP服务程序就会注入 /debug/pprof 相关的路由，可以访问 http://localhost:8090/debug/pprof/ 查看总览，如下所示

1
2
3
4
5
6
7
8
9
10
11
12
13
/debug/pprof/

Types of profiles available:
Count        Profile
3        allocs
0        block
0        cmdline
4        goroutine
3        heap
0        mutex
0        profile
7        threadcreate
0        trace

下面是各种 profile 的描述：

  • allocs: A sampling of all past memory allocations. 过去所有内存分配的抽样。
  • block: Stack traces that led to blocking on synchronization primitives. 导致同步原语阻塞的堆栈跟踪。
  • cmdline: The command line invocation of the current program. 当前程序的命令行调用。
  • goroutine: Stack traces of all current goroutines. 堆栈当前所有goroutines的跟踪。
  • heap: A sampling of memory allocations of live objects. You can specify the gc GET parameter to run GC before taking the heap sample. 活动对象的内存分配抽样。在获取堆样本之前，可以指定gc GET参数来运行gc。
  • mutex: Stack traces of holders of contended mutexes. 竞争互斥锁持有者的堆栈跟踪。
  • profile: CPU profile. You can specify the duration in the seconds GET parameter. After you get the profile file, use the go tool pprof command to investigate the profile. CPU profile。可以在GET参数中指定以秒为单位的持续时间，默认是30s。在获得profile文件之后，使用go工具pprof命令来研究它。
  • threadcreate: Stack traces that led to the creation of new OS threads. 导致创建新的操作系统线程的堆栈跟踪。
  • trace: A trace of execution of the current program. You can specify the duration in the seconds GET parameter. After you get the trace file, use the go tool trace command to investigate the trace. 当前程序执行的痕迹。可以在GET参数中指定以秒为单位的持续时间。在获得trace文件之后，使用go工具 trace 命令来研究它。

pprof工具的交互式终端

使用方法
1
2
3
4
5
# 方法一
go tool pprof ${source}

# 方法二，前提是要安装 pprof ，具体方法请查看“ pprof 工具准备”章节
pprof ${source}

source可以是通过”net/http/pprof” 包提供的http url ，也可以是本地 profile 文件。

cpu分析
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
$ go tool pprof http://localhost:8090/debug/pprof/profile?seconds=15

Fetching profile over HTTP from http://localhost:8090/debug/pprof/profile?seconds=15
Saved profile in /Users/xxx/pprof/pprof.samples.cpu.004.pb.gz
Type: cpu
Time: Apr 5, 2022 at 3:13pm (CST)
Duration: 15s, Total samples = 290ms ( 1.93%)
Entering interactive mode (type "help" for commands, "o" for options)
(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

执行该命令后，需等待seconds参数指定的时间（默认30s），采样完成后，即可用交互式命令进行分析，具体可以使用 help 指令查看说明，比如 top 可以查看占用 cpu 最多的 n 个记录。

1
2
3
4
5
6
7
(pprof) top
Showing nodes accounting for 290ms, 100% of 290ms total
      flat  flat%   sum%        cum   cum%
     280ms 96.55% 96.55%      280ms 96.55%  github.com/rukesun/go-learning/examples/pprof/internal/simulator.(*XXCPU).Run
      10ms  3.45%   100%       10ms  3.45%  runtime.memmove
         0     0%   100%       10ms  3.45%  github.com/rukesun/go-learning/examples/pprof/internal/simulator.(*XXHeap).Run
         0     0%   100%       10ms  3.45%  runtime.growslice
  • flat：该位置的运行耗时
  • flat%：该位置的 CPU 运行耗时总比例
  • sum%：该位置累积使用 CPU 总比例
  • cum：该位置加上它的子调用运行总耗时
  • cum%：该位置加上它的的子调用的 CPU 运行耗时总比例

最后一列为函数调用的位置。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
(pprof) help list
Output annotated source for functions matching regexp
  Usage:
    list<func_regex|address> [-focus_regex]* [-ignore_regex]*
    Include functions matching func_regex, or including the address specified.
    Include samples matching focus_regex, and exclude ignore_regex.

(pprof) list Run
Total: 300ms
ROUTINE ======================== github.com/rukesun/go-learning/examples/pprof/internal/simulator.(*XXCPU).Run in /Users/ht/research/golang/go-learning/examples/pprof/internal/simulator/xxcpu.go
     270ms      300ms (flat, cum)   100% of Total
         .          .     16:}
         .          .     17:
         .          .     18:func (c *XXCPU) Run() {
         .          .     19:        log.Printf("%v Run", c.Name())
         .          .     20:        loop := 1000000000
     270ms      300ms     21:        for i := 0; i < loop; i++ {
         .          .     22:                // do nothing
         .          .     23:        }
         .          .     24:}

通过list命令可以查看关联的代码，比如这里可以看出XXCPU的Run方法里面，有个循环的代码会消耗较多的 cpu 。

内存分析

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:8090/debug/pprof/heap

(pprof) top
Showing nodes accounting for 36353.94kB, 100% of 36353.94kB total
Showing top 10 nodes out of 20
      flat  flat%   sum%        cum   cum%
   32768kB 90.14% 90.14%    32768kB 90.14%  github.com/rukesun/go-learning/examples/pprof/internal/simulator.(*XXHeap).Run
 2048.81kB  5.64% 95.77%  2048.81kB  5.64%  runtime.malg
 1025.12kB  2.82% 98.59%  1025.12kB  2.82%  runtime.allocm
     512kB  1.41%   100%      512kB  1.41%  runtime.doaddtimer
         0     0%   100%      512kB  1.41%  runtime.mcall
         0     0%   100%      512kB  1.41%  runtime.modtimer
         0     0%   100%  1025.12kB  2.82%  runtime.mstart
         0     0%   100%  1025.12kB  2.82%  runtime.mstart0
         0     0%   100%  1025.12kB  2.82%  runtime.mstart1
         0     0%   100%  1025.12kB  2.82%  runtime.newm
(pprof) list Run
Total: 35.50MB
ROUTINE ======================== github.com/rukesun/go-learning/examples/pprof/internal/simulator.(*XXHeap).Run in /Users/xxx/research/golang/go-learning/examples/pprof/internal/simulator/xxheap.go
      32MB       32MB (flat, cum) 90.14% of Total
         .          .     17:}
         .          .     18:
         .          .     19:func (h *XXHeap) Run() {
         .          .     20:        log.Printf("%v Run", h.Name())
         .          .     21:        for i := 0; i < 10; i++ {
      32MB       32MB     22:                h.data = append(h.data, [1024 * 1024]byte{})
         .          .     23:        }
         .          .     24:        log.Printf("After %v Run, len:%v, cap:%v", h.Name(), len(h.data), cap(h.data))
         .          .     25:}

同样通过top和list大法，找出内存分配较多的地方。

协程分析
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
$ go tool pprof http://localhost:8090/debug/pprof/goroutine

Fetching profile over HTTP from http://localhost:8090/debug/pprof/goroutine
Saved profile in /Users/xxx/pprof/pprof.goroutine.001.pb.gz
Type: goroutine
Time: Apr 5, 2022 at 3:24pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)

(pprof) top
Showing nodes accounting for 3002, 100% of 3003 total
Dropped 27 nodes (cum <= 15)
      flat  flat%   sum%        cum   cum%
      3002   100%   100%       3002   100%  runtime.gopark
         0     0%   100%       3000 99.90%  github.com/rukesun/go-learning/examples/pprof/internal/simulator.(*XXGoroutine).Run.func1
         0     0%   100%       3000 99.90%  time.Sleep

(pprof) list Run
Total: 3003
ROUTINE ======================== github.com/rukesun/go-learning/examples/pprof/internal/simulator.(*XXGoroutine).Run.func1 in /Users/xxx/research/golang/go-learning/examples/pprof/internal/simulator/xxgoroutine.go
         0       3000 (flat, cum) 99.90% of Total
         .          .     18:
         .          .     19:func (g *XXGoroutine) Run() {
         .          .     20:        log.Printf("%v Run", g.Name())
         .          .     21:        for i := 0; i < 1000; i++ {
         .          .     22:                go func() {
         .       3000     23:                        time.Sleep(3600 * time.Second)
         .          .     24:                }()
         .          .     25:        }
         .          .     26:}
ROUTINE ======================== runtime/pprof.writeRuntimeProfile in /Users/xxx/.gvm/gos/go1.18/src/runtime/pprof/pprof.go
         0          1 (flat, cum) 0.033% of Total

同样通过top和list大法，找出协程分配较多的地方。

pprof工具的可视化界面

使用方法
1
2
3
4
5
6
7
8
9
# 方法一
go tool pprof -http=:8091 ${source}

# 方法二，前提是要安装 pprof ，具体方法请查看“ pprof 工具准备”章节
pprof -http=:8091 ${source}

# 方法三，在交互式界面上执行 web 指令
go tool pprof ${source}
(pprof) web
cpu分析

执行命令

1
go tool pprof -http=:8091 http://localhost:8090/debug/pprof/profile?seconds=15

可视化Graph
cpu_profile_graph_view
框越大线越粗，代表该代码处占用的时间越长。

可视化Top
cpu_profile_top_view

可视化火焰图
cpu_profile_flame_graph

火焰图（Flame Graph）是由 Linux 性能优化大师 Brendan Gregg 发明的，它以一个全局的视野来看待时间分布，并且列出所有可能导致性能瓶颈的调用栈。
火焰图有以下特征：

  • 每一列代表一个调用栈，每一个格子代表一个函数。
  • 纵轴展示了栈的深度，正立火焰图按照调用关系从下到上排列（倒立火焰图方向刚好相反）。
  • 横轴部分，火焰图将采集的多个调用栈信息，通过按字母横向排序的方式将众多信息聚合在一起。需要注意的是它并不代表时间的先后。横轴格子的宽度代表其在采样中出现频率，所以一个格子的宽度越大，说明它是瓶颈原因的可能性就越大。
  • 火焰图格子的颜色是随机的暖色调，方便区分各个调用信息。

可视化Peek
cpu_profile_peek_view

可视化Source
cpu_profile_source_view

内存分析
1
go tool pprof -http=:8091 http://localhost:8090/debug/pprof/heap

可视化Graph
heap_profile_graph_view
其他图表请参考 cpu 分析部分，这里不再一一列举。

协程分析

执行命令

1
go tool pprof -http=:8091 http://localhost:8090/debug/pprof/goroutine

可视化Graph
goroutine_profile_graph_view
其他图表请参考 cpu 分析部分，这里不再一一列举。

使用runtime/pprof生成profile文件调试

之前的章节使用 net/http/pprof 提供的 HTTP 接口进行调试分析，如果是非 HTTP 的程序或者因为数据安全问题，我们不想暴露 HTTP 接口，那么我们该如何分析调试？答案是在代码中引入 runtime/pprof 包，示例代码如下：

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
var cpuprofile = flag.String("cpuprofile", "", "write cpu profile to `file`")
var memprofile = flag.String("memprofile", "", "write memory profile to `file`")

func main() {
    flag.Parse()
    if *cpuprofile != "" {
        f, err := os.Create(*cpuprofile)
        if err != nil {
            log.Fatal("could not create CPU profile: ", err)
        }
        defer f.Close() // error handling omitted for example
        // 启动CPU Profile
        if err := pprof.StartCPUProfile(f); err != nil {
            log.Fatal("could not start CPU profile: ", err)
        }
        // 停止CPU Profile
        defer pprof.StopCPUProfile()
    }

    // ... rest of the program ...

    if *memprofile != "" {
        f, err := os.Create(*memprofile)
        if err != nil {
            log.Fatal("could not create memory profile: ", err)
        }
        defer f.Close() // error handling omitted for example
        runtime.GC() // get up-to-date statistics
        // 生成当前内存统计的 Heap Profile
        if err := pprof.WriteHeapProfile(f); err != nil {
            log.Fatal("could not write memory profile: ", err)
        }
    }
}

完整代码请参考 demo 工程的 pprof/internal/xxprof/xxprof.go ，通过上面的代码生成相关的 profile 文件之后，使用 pprof 工具即可分析调试。

另外，为了便于使用，我们可以结合 signal 来使用，示例代码

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
package xxsignal

import (
        "log"
        "os"
        "os/signal"
        "syscall"

        "github.com/rukesun/go-learning/examples/pprof/internal/xxprof"
)

func init() {
        go func() {
                var profiler *xxprof.Profile

                signals := make(chan os.Signal, 1)
                signal.Notify(signals, syscall.SIGUSR1, syscall.SIGUSR2)

                for {
                        v := <-signals
                        log.Printf("Got signal:", v)
                        switch v {
                        case syscall.SIGUSR1:
                        case syscall.SIGUSR2:
                                if profiler == nil {
                                        profiler = xxprof.NewProfile()
                                        profiler.Start()
                                } else {
                                        profiler.Stop()
                                        profiler = nil
                                }
                        default:
                                log.Printf("Got unregistered signal:", v)
                        }
                }
        }()
}

在需要使用的程序 import xxsignal ，然后通过kill发送相关的信号即可。注意，使用 signal 时，需要使用 go build 编译成二进制可执行文件，通过 go run 的方式则不能捕获相关的信号。

1
kill -SIGUSR2 ${pid}

参考资料

  1. Debugging in Visual Studio Code, https://code.visualstudio.com/docs/editor/debugging
  2. Running | Goland, https://www.jetbrains.com/help/go/running-applications.html
  3. Debugging | Goland, https://www.jetbrains.com/help/go/debugging-code.html
  4. PProf README, https://github.com/google/pprof/blob/master/doc/README.md
  5. Profiling a Go program, https://pkg.go.dev/runtime/pprof@go1.18#hdr-Profiling_a_Go_program
  6. Go tool pprof, https://github.com/eddycjy/blog/blob/master/content/posts/go/tools/2018-09-15-go-tool-pprof.md
  7. Go pprof practice, https://blog.wolfogre.com/posts/go-ppof-practice/
  8. Go Zero profile, https://github.com/zeromicro/go-zero/blob/master/core/proc/profile.go
感谢你的阅读，如果文章对你有帮助，可以请作者喝杯茶!