go profile

简介

Go语言的性能分析工具pprof是Google C++ profiler的移植,非常有趣。

cpu profile

If the code used the Go testing package’s benchmarking support, we could use gotest’s standard -cpuprofile and -memprofile flags. In a standalone program like this one, we have to import runtime/pprof and add a few lines of code:

履行程序，同时指定-cpuprofile flag，生成profile文件，我们的go程序的binary是go_cpu_pro:

运行go tool pprof解释生成的profile，同时进入pprof环境后，可以用help命令查看帮助信息，最经常使用的命令如top10，可以看最耗时的function:

当CPU profiling开启时，Go程序每秒采样大约100次，1个采样由在当前正在履行的goroutine的堆栈上的程序计数器组成，这个profile有51.11*100=51110次采样，总时间是51.11s，在go tool pprof的输出中，每行是1个function，各列的含义顺次是:

• 采样点落在该函数中的次数
• 采样点落在该函数中的百分比
• 上1项的积累百分比
• 采样点落在该函数，和被它调用的函数中的总次数
• 采样点落在该函数，和被它调用的函数中的总次数百分比
• 函数名

To sort by the fourth and fifth columns, use the -cum (for cumulative) flag:

我们还可使用web指令生成函数调用关系图，web命令会生成1个SVG格式的图片，我们需要预先安装graphviz，Ubuntu上我们可以用sudo apt-get install graphviz

图片中，每一个box是1个function，并且依照该function运行的采样数改变box的尺寸，从X到Y的1条边代表着X calls Y，Edge上面的数字是这个调用出现在1个采样的次数。例如：runtime.mapaccess1_fast64 3.72s(7.28%) of 4.08s(7.98%)，其中3.72s表示全部采样中，有3.72*100次runtime.mapaccess1_fast64正在运行，4.08s表示全部采样中，有4.08*100次堆栈中包括runtime.mapaccess1_fast64，runtime.mapaccess1_fast64到runtime.aeshash64那条边表示函数调用，上面的数字0.36s表示，全部采样中唯一0.36*100次采样捕捉到了runtime.mapaccess1_fast64对runtime.aeshash64的调用。

我们还可使用web指令，仅查看某个function的调用关系图，例如runtime.mapaccess1_fast64：

查看函数内，每行代码的采样数:

The listing shows the source code for the DFS function (really, for every function matching the regular expression DFS). The first three columns are the number of samples taken while running that line, the number of samples taken while running that line or in code called from that line, and the line number in the file. The related commanddisasmshows a disassembly of the function instead of a source listing; when there are enough samples this can help you see which instructions are expensive. Theweblistcommand mixes the two modes:it shows a source listing in which clicking a line shows the disassembly.

some hints

Here are some hints with respect to how to interpret what you see in the profile.

If you see lots of time spent in runtime.mallocgc function, the program potentially makes excessive amount of small memory allocations. The profile will tell you where the allocations are coming from. See the memory profiler section for suggestions on how to optimize this case.

If lots of time is spent in channel operations, sync.Mutex code and other synchronization primitives or System component, the program probably suffers from contention. Consider to restructure program to eliminate frequently accessed shared resources. Common techniques for this include sharding/partitioning, local buffering/batching and copy-on-write technique.

If lots of time is spent in syscall.Read/Write, the program potentially makes excessive amount of small reads and writes. Bufio wrappers around os.File or net.Conn can help in this case.

If lots of time is spent in GC component, the program either allocates too many transient objects or heap size is very small so garbage collections happen too frequently. See Garbage Collector Tracer and Memory Profiler sections for optimization suggestions.

如果大量的时间消耗在runtime.mallocgc的函数，那末暗示程序产生了大量过度的小内存分配工作。查看内存分析器部份可以取得如何优化这类情况的建议。

如果大量的时间消耗在channel operations, sync.Mutex code and other synchronization primitives or System component，那末程序极可能正在饱受资源竞争的痛苦。

如果大量的时间消耗在syscall.Read/Write，那末暗示程序产生了大量过度的小块读写。对这类情况，Bufio会很有帮助。

如果大量的时间消耗在GC component，那末程序或分配了大量短暂的对象，或堆size太小了。

memory profile

与cpu profile相同，memory profile也需要导入runtime/pprof，同时增加1些代码:

履行程序，同时指定-memprofile flag，生成profile文件，我们的go程序的binary是go_mem_pro:

运行go tool pprof解释生成的profile，进入pprof环境:

现在这个采样是内存分配, not clock ticks. To find the memory allocations, we can list those functions.

顺便说1句, 假设我们运行go tool pprof与--inuse_objectsflag, it will report allocation counts instead of sizes:

还有，我们可使用–nodefraction=0.1 告知go tool pprof忽视掉低于10%的采样的box，固然数字我们是可以改的，下面是2次修改nodefraction的对照:

heap profile

The numbers in the beginning of each entry (“1: 262144 [4: 376832]”) represent number of currently live objects, amount of memory occupied by live objects, total number of allocations and amount of memory occupied by all allocations, respectively.

每一个条目开头的数字（”1: 262144 [4: 376832]”）分别表示目前存活的对象，存活对象占据的内存， 分配对象的个数和所有分配对象占据的内存总量。

block profile

Note that not all blocking is bad. When a goroutine blocks, the underlying worker thread simply switches to another goroutine. So blocking in the cooperative Go environment is very different from blocking on a mutex in a non-cooperative systems (e.g. typical C++ or Java threading libraries, where blocking leads to thread idling and expensive thread context switches). To give you some feeling, let’s consider some examples.

Blocking on a time.Ticker is usually OK. If a goroutine blocks on a Ticker for 10 seconds, you will see 10 seconds of blocking in the profile, which is perfectly fine. Blocking on sync.WaitGroup is frequently OK. For example, is a task takes 10 seconds, the goroutine waiting on a WaitGroup for completion will account for 10 seconds of blocking in the profile. Blocking on sync.Cond may or may not be OK, depending on the situation. Consumer blocking on a channel suggests slow producers or lack of work. Producer blocking on a channel suggests that consumers are slower, but this is frequently OK. Blocking on a channel-based semaphore shows how much goroutines are gated on the semaphore. Blocking on a sync.Mutex or sync.RWMutex is usually bad.

并不是所有的阻塞都是不利的。当1个goroutine阻塞时，底层的工作线程就会简单地转换到另外一个goroutine。所以Go并行环境下的阻塞与非并行环境下的mutex的阻塞是有很大不同的（例如典型的C++或Java线程库，当产生阻塞时会引发线程空载和高昂的线程切换）。几个例子:

在time.Ticker上产生的阻塞通常是可行的，如果1个goroutine阻塞Ticker超过10秒，你将会在profile中看到有10秒的阻塞，这是很好的。产生在sync.WaitGroup上的阻塞常常也是可以的，例如，1个任务需要10秒，等待WaitGroup完成的goroutine会在profile中生成10秒的阻塞。产生在sync.Cond上的阻塞可好可坏，取决于情况不同。消费者在通道阻塞表明生产者缓慢或不工作。生产者在通道阻塞，表明消费者缓慢，但这通常也是可以的。在基于channel-based semaphore产生阻塞，表明了限制在这个信号量上的goroutine的数量。产生在sync.Mutex或sync.RWMutex上的阻塞通常是不利的。你可以在可视化进程中，在pprof中使用–ignore标志来从profile中排除已知的无关阻塞。

goroutinue profile

The goroutine profiler simply gives you current stacks of all live goroutines in the process. It can be handy to debug load balancing issues (see Scheduler Trace section below), or to debug deadlocks. The profile makes sense only for a running app, so go test does not expose it.

Note that goroutines in “syscall” state consume an OS thread, other goroutines do not (except for goroutines that called runtime.LockOSThread, which is, unfortunately, not visible in the profile). Note that goroutines in “IO wait” state also do not consume threads, they are parked on non-blocking network poller (which uses epoll/kqueue/GetQueuedCompletionStatus to unpark goroutines later).

goroutinue分析器简单地提供给你当前进程中所有活跃的Go协程堆栈。它可以方便地调试负载平衡问题（参考下面的调度器追踪章节），或调试死锁。这个配置仅仅对运行的程序成心义，所以go test是没用的。

syscall状态的goroutinue将会消耗1个OS线程，而其他的Go协程则不会（除调用runtime.LockOSThreadd的goroutinue，不幸的是，它在profile中是不可见的）。一样需要注意的是在IO wait状态的goroutinue一样不会消耗线程，他们停驻在非阻塞的网络轮询器（通常稍后使用epoll/kqueue/GetQueuedCompletionStatus来唤醒goroutines）。

Garbage Collector Trace

$ GODEBUG=gctrace=1 ./myserver

Then the program will print output similar to the following during execution:

Let’s consider the meaning of these numbers. One line per GC is printed. The first number (“gc9”) is the number of GC (this is the 9-th GC since program start). The number in parens (“(2)”) is the number of worker threads participated in the GC. The next 4 numbers (“12+1+744+8 us”) mean stop-the-world, sweeping, marking and waiting for worker threads to finish, in microseconds, respectively. The next 2 numbers (“2 -> 10 MB”) mean size of live heap after the previous GC and full heap size (including garbage) before the current GC. The next 3 numbers (“108615 (593983⑷85368) objects”) are total number of objects in heap (including garbage) and total number of memory allocation and free operations. The next 3 numbers (“4825/3620/0 sweeps”) characterize sweep phase (of the previous GC): there were total 4825 memory spans, 3620 were swept on demand or in background, 0 were swept during stop-the-world phase (the rest were unused spans). The next 4 numbers (“0(0) handoff, 6(91) steal”) characterize load balancing during parallel mark phase: there were 0 object handoff operations (0 objects were handoff), and 6 steal operations (91 objects were stolen). The last 3 numbers (“16/1/0 yields”) characterize effectiveness of parallel mark phase: there were total of 17 yield operations during waiting for another thread.

每次GC输出1行。

• 第1个数字（”gc9”）是GC的编号（这是从程序开始后的第9个GC），在括号中的数字（”(2)”）是参与GC的工作线程的数量。
• 随后的4个数字（”12+1+744+8 us”）分别是工作线程完成GC的stop-the-world, sweeping, marking和waiting时间，单位是微秒。
• 接下来的两个数字（”2 -> 10 MB”）表示前1个GC过后的活跃堆大小和当前GC开始前全部的堆（包括垃圾）的大小。
• 再接下来的3个数字 （”108615 (593983⑷85368) objects”）是堆中的对象总数（包括垃圾）和分配操作的内存总数和释放操作的内存总数。
• 后面的3个数字（”4825/3620/0 sweeps”）表示sweep phase (of the previous GC)：总共有4825个memory spans，3620立即或在后台清除，0个在stop-the-world阶段清除（剩余的是没有使用的spans）。
• 再后面的4个数字（”0(0) handoff, 6(91) steal”）表示了load balancing during parallel mark phase：there were 0 object handoff operations (0 objects were handoff), and 6 steal operations (91 objects were stolen).
• 最后的3个数字（”16/1/0 yields”）表示了effectiveness of parallel mark phase：there were total of 17 yield operations during waiting for another thread.

Memory Allocator Trace

内存分配器跟踪只是简单地将所有的内存分配和释放操作转储到控制台。通过设置环境变量GODEBUG=allocfreetrace=1就能够开启该功能。输出看起来像下面的内容：

The trace contains address of the memory block, size, type, goroutine id and the stack trace.

Scheduler Trace

调度器追踪可以提供对 goroutine 调度的动态行动的内视，并且可以用来调试负载平衡和可扩大性问题。要启用调度器追踪，可以带有环境变量 GODEBUG=schedtrace=1000来运行程序(这个值的意思是输出的周期，单位是ms，这类情况下是每秒1次):

The first number (“1004ms”) is time since program start. Gomaxprocs is the current value of GOMAXPROCS. Idleprocs is the number of idling processors (the rest are executing Go code). Threads is the total number of worker threads created by the scheduler (threads can be in 3 states: execute Go code (gomaxprocs-idleprocs), execute syscalls/cgocalls or idle). Idlethreads is the number of idling worker threads. Runqueue is the length of global queue with runnable goroutines. The numbers in square brackets (“[0 1 0 3]”) are lengths of per-processor queues with runnable goroutines. Sum of lengths of global and local queues represents the total number of goroutines available for execution.

• 第1个数字（”1004ms”）是从程序开始后的时间。
• Gomaxprocs 是当前的 GOMAXPROCS 值。
• Idleprocs 是空闲的处理器数（剩下的在履行 Go 代码）。
• Threads 是调度器产生的worker线程总数（线程有3种状态：履行 Go 代码（gomaxprocs-idleprocs），履行 syscalls/cgocalls，闲置）。
• Idlethreads是闲置的worker线程数。
• Runqueue 是可运行的 goroutine 的全局队列长度。方括号中的数字（”[0 1 0 3]”）是每一个processor的可运行的 goroutine 的队列的长度。全局和局部队列的长度总和表示可履行的 goroutine 的总数。

当1个程序不与 GOMAXPROCS 成线性比例和(或)没有消耗100%的CPU时间(top 命令)，Scheduler Trace就显得非常有用。

理想的情况是：所有的处理器都在繁忙地运行 Go 代码，线程数公道，所有队列都有充足的任务且任务是公道均匀的散布的：

不好的情况是上面所列的东西并没有完全到达。例以下面这个演示，没有足够的任务来保持所有的处理器繁忙：

你可使用 goroutine profile来了解哪些goroutine块处于任务短缺状态。注意，只要所有的处理器处于忙绿状态，负载失衡就不是最坏的，它只会致使适度的load balance开消。

Memory Statistics

Go runtime exposes coarse-grained memory statistics viaruntime.ReadMemStatsfunction. The statistics are also exposed vianet/http/pprofat the bottom ofhttp://myserver:6060/debug/pprof/heap?debug=1. The statistics are described here.

Some of the interesting fields are:

• HeapAlloc - current heap size.
• HeapSys - total heap size.
• HeapObjects - total number of objects in the heap.
• HeapReleased - amount of memory released to the OS; runtime releases to the OS memory unused for 5 minutes, you can force this process withruntime/debug.FreeOSMemory.
• Sys - total amount of memory allocated from OS.
• Sys-HeapReleased - effective memory consumption of the program.
• StackSys - memory consumed for goroutine stacks (note that some stacks are allocated from heap and are not accounted here, unfortunately there is no way to get total size of stacks (https://code.google.com/p/go/issues/detail?id=7468)).
• MSpanSys/MCacheSys/BuckHashSys/GCSys/OtherSys - amount of memory allocated by runtime for various auxiliary purposes; they are generally not interesting, unless they are too high.
• PauseNs - durations of last garbage collections.

profile使用方式汇总

httpServer pprof

如果你的go程序是用http包启动的web服务器，你想查看自己的web服务器的状态。这个时候就能够选择net/http/pprof。你只需要引入包_ “net/http/pprof”，然后就能够在阅读器中使用http://localhost:port/debug/pprof/直接看到当前web服务的状态，包括CPU占用情况和内存使用情况等。

Use the pprof tool to look at the heap profile:

Or to look at a 30-second CPU profile:

Or to look at the goroutine blocking profile, after callingruntime.SetBlockProfileRatein your program:

Or to collect a 5-second execution trace:

To view all available profiles, open http://localhost:6060/debug/pprof/ in your browser.

service pprof

如果你的go程序不是web服务器，而是1个服务进程，那末我们可以将profile信息输出到阅读器或文件。

访问http://localhost:11181/，我们就能够得到全部goroutine的信息。也能够将profile信息写入文件或标准输出:

go test

go test内建了多个flag，用于输出profile: