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: