本文主要讲解如何调试golang程序，内容包括 GODEBUG 和 性能分析(pprof) 两部分。

案例代码在

要使测试某个用例的时候，在main.go中取消相应的注释即可。

GODEBUG

GODEBUG 变量是控制 runtime调试变量的变量。调试的变量有点多，这里就挑几个讲重要的讲解。详情可以移步

gctrace

设置 gctrace=1 会使 垃圾回收器 在每次GC时，打印一行设涉及到GC的信息，同时汇总收集的内存量和暂停的时间。

咱们结合用例代码的输出来说说每列数据的意思。输出如下:

随便挑一行来收说

这里重点说一下 wall-clock 和 cpu 时间的区别

wall-clock time：是指程序开始执行到完成所经历的实际时间(墙上挂钟时间)

cpu time：是指程序使用 CPU 的时间

他们存在以下关系：

这一行的内容是在 "slice alloc end"之前。 之后我们手动执行 "runtime.GC()"， gc 23 这一行 后面 “(forced)” 就代表了 被 runtime.GC() 强制执行。然后我们看到当前活跃内存的大小已经为0。但是发现全局堆大小是 888 M，即当前进程还占用了888M进程，这些都是空闲内存，它会慢慢被系统回收。

inittrace

inittrace=1

像上面一样，咱们直接看用例输出(这里只需要把 init_package1、init_package2引入到main.go中即可)

挑一行来解释

从输出，我们还可以看到 依赖包里面依赖包的内容。打印顺序同依赖顺序

madvdontneed

madvdontneed=1(madvdontneed=0, MADV_FREE)

schedtrace

schedtrace=X

看看用例输出

老规矩，随便找一行来说明

scheddetail

schedtrace=X,scheddetail=1

用例同schedtrace，只需要多加一个GODEBUG参数即可。输出如下

这里我们能详细的看到 一个时间段的 GMP相关信息。分析上面详情内容之前，咱们先了解一下G包含哪些状态:

以及 P (processor)包含的状态:

然后我们再解释输出的内容

性能分析(pprof)

"runtime/trace"_ "net/http/pprof"

我们直接使用 go 自带的性能分析工具即可， 而且最火焰图早已经已经集成进了 go tool pprof。

用例直接在 main.go 里能很清晰的看到，相应的取消注释即可，同时记得要放开下面的

cpu分析

go run main.gogo tool pprof -http=:端口 "http://127.0.0.1:8989/debug/pprof/profile?seconds=60"

60s 后，生成了报告文件 XXX.pb.gz，同时自动打开一个web页面展示分析结果。

我们直接在View里选中 Flame Graph(火焰图) 展示即可。读者可以自己测试，这里就不截图展示了。可以很清晰的看出每个方法消耗的cpu time，以及子方法的时间占比，从用例中我们发现wasteCPU方法占用了大量时间。

heap分析

go run main.gogo tool pprof -http=:端口 "http://127.0.0.1:8989/debug/pprof/heap?seconds=60"
SAMPLE标签

协程栈分析

race

这里没有用例，因为写出一个有数据竞争的协程例子很容易。

go build -raceWARNING: DATA RACE

协程泄漏

/debug/pprof/goroutine

我们发现大量的协程调用栈最终都会指向 runtime.gopark 函数。 

_Gwaiting

其实我们通过 直接访问 127.0.0.1:8989/debug/pprof 发现goroutine的数量不断增加，也可以初步判断协程泄漏了

mutex阻塞分析

即我们分析互斥锁的竞争情况。

/debug/pprof/mutex?seconds=30

在报告中我们会发现互斥锁带来的协程休眠时间是30s 左右， 所以我们可以断定 cpu利用率不高，大量的时间浪费在了这里，需要调整锁临界区(lock与Unlock之间的代码区域)的代码。


trace事件追踪

基于上文的各种分析指标，其实已经能覆盖大部分场景了。

但那些指标并没有提供 Goroutine 整个周期内(生成报告的时间内)发生的时间，例如 Goroutine 何时创建、执行了多少时间、调度到了哪个processor上执行、GC如何影响协程的 等等信息。

go1.5在之后的推出的， 它提供了指定时间内程序发生的事件的完整信息，包括:

  1. 协程的创建、开始和结束
  2. 协程的阻塞 -- 系统调用、通道、锁
  3. 网络I/O相关事件
  4. 系统调用事件
  5. 垃圾回收相关事件

用例在这

这里有点不同的是，为了方便测试使用的是"runtime/trace"依赖包。也可以使用接口的方式再配合压测，也能得出报告。执行方式如下：

这里工具也不再是 pprof， 而是trace

然后我们就得出报告界面:

从简单到复杂，一点一点来看（只挑几个重点讲）

咱们先看最简单的，点击 "Scheduler latency profile"：

这个图咱们不陌生，跟 cpu 分析出来的结果展示一样，就是一个方法调用链加时间的图。


然后再点击 "Goroutine analysis":

可以看到具体哪些协程。旁边的 N 表示数量。

点击一个协程 "go_debug/example/pprof.TestTrace·dwrap·2" 可以看到其编号，以及在整个运行过程中，各类时间的占比

最后看 点击 “View trace” 查看程序整个生命周期中各个 Goroutine 发生的事情，比如什么时候发生了GC、协程被调度到了哪个 processor：

我在图上做了几个红色的编号：

我们点击第一个绿色的协程执行片段(go_debug/example/pprof.TestTrace dwrap 2)，会看到下面的信息


总结

如果把我们的golang 进程当作一个黑盒(不了解代码)，通过上文我们可以从宏观(GODEBUG)、微观(pprof + trace) 两个维度得出来的指标信息，来分析出该进程存在哪些问题。

不仅如此，从这么多年的从业经验来看，在测试阶段工程师有性能分析的好习惯(比如本身就存在 内存泄漏、协程泄漏)，可以有效避免线上一些奇怪的事故，功能测试是很难测出这类问题的。