golang 性能診斷看這篇就夠了

我們日常接觸性能診斷問題，一般分爲兩種情況，一是線上應用真的出現性能問題；二是我們需要對準備上線的系統進行性能預估；後者需要壓力測試輔助進行，此處不表。

針對 GO 應用，性能診斷工具主要分爲兩層: OS 層面和 GO 應用層面 (go tool pprof /trace /gc)

OS 診斷

系統診斷，我們一般主要關注三個方面: CPU 、Memory、I/O

1.1 CPU

CPU 診斷主要關注平均負載（Load Average），CPU 使用率，上下文切換（Context Switch）。常用 top 命令查看 cpu 使用率以及服務器負載情況。

平均負載: 0.14 0.07 0.06 分別表示過去 1 分鐘、5 分鐘、15 分鐘的機器負載的平均值，根據經驗，若負載數值小於 0.7*CPU 個數則正常，超過或者達到 CPU 核數的四五倍，則系統的負載就明顯偏高。

CPU 的上下文切換情況可通過 vmstat 命令可以查看，上下文切換髮生的場景有如下幾種:

時間片用完，CPU 正常調度下一個任務
被其他優先級更高的任務搶佔
執行任務碰到 I/O 阻塞，掛起當前任務，切換到下一個任務
用戶代碼主動掛起當前任務讓出 CPU
多任務搶佔資源，因沒搶到而被掛起
硬件中斷

1.2 Memory

從操作系統角度，內存關注應用進程是否足夠，可以使用 free –m 命令查看內存的使用情況。

通過 top 命令可以查看進程使用的虛擬內存 VIRT 和物理內存 RES，根據公式 VIRT = SWAP + RES 可以推算出具體應用使用的交換分區（Swap）情況，使用交換分區過大會影響應用性能，可以將 swappiness 值調到儘可能小。

1.3 I/O

I/O 包括磁盤 I/O 和網絡 I/O，一般情況下磁盤更容易出現 I/O 瓶頸。通過 iostat 可以查看磁盤的讀寫情況，通過 CPU 的 I/O wait 可以看出磁盤 I/O 是否正常。

如果磁盤 I/O 一直處於很高的狀態，說明磁盤太慢或故障，成爲了性能瓶頸，需要進行應用優化或者磁盤更換。

除了常用的 top、 ps、vmstat、iostat 等命令，還有其他 Linux 工具可以診斷系統問題，如 mpstat、tcpdump、netstat、pidstat、sar 等更多 Linux 性能診斷工具如下圖：

GO 應用診斷

go 生態已經爲我們提供了大量的 API 和診斷工具幫助我們解決 go 應用的性能問題。我們常用的大致可以分爲兩類:

Profiling 收集程序執行過程中的具體事件，並抽樣統計方便精確定位問題
Tracing 一種檢測代碼的方法，用於分析調用或用戶請求整個生命週期中的延遲，且可以跨多個 Go 進程。

2.1 profiling

profile 一般被稱爲性能分析，對程序而言，就是程序運行時的各種概況信息，包括 cpu 佔用情況、內存情況、線程情況等。方便分析昂貴或頻繁調用的程序場景。

如何使用？

首先 profiling 代碼埋入

1import _ "net/http/pprof"
2func main() {
3    go func() {
4        log.Println(http.ListenAndServe("0.0.0.0:9090", nil))
5    }()
6    ...
7}
8

保存特定時間點的 profile，例如保存 heap 信息

1curl http://localhost:6060/debug/pprof/heap --output heap.tar.gz
2

使用 go tool pprof 分析保存的 profile 快照，如分析上述 heap 信息

1go tool pprof heap.tar.gz
2

2.1.1 CPU Profiling

pprof 可以幫忙我們分析出函數執行緩慢問題 CPU 佔用過高問題

1go tool pprof http://localhost:6060/debug/pprof/profile?second=10
2

命令行方式: 常用命令 top list traces

top: 查看按照佔用內存或 cpu 多少排序的前 10 的函數信息

flat: 當前函數佔用的 CPU 時長（不包含其調用的其他函數）
flat%: 當前函數使用 CPU 佔總 CPU 時長的百分比
sum%: 前面每一行 flat 百分比的和
cum: 累計量，當前函數及其子函數佔用 CPU 時長
cum%: 累計量佔總量的百分比

cum>=flat

list: 查看某個函數的代碼以及該函數每行代碼的指標信息

traces: 打印所有函數調用棧以及調用棧的指標信息

UI 界面方式：從服務器 download 下生成的 sample 文件

1go tool pprof -http=:8080 pprof.xxx.samples.cpu.001.pb.gz
2

Flame graph 很清晰得可以看到當前 CPU 被哪些函數執行棧佔用

1.2 Heap Profiling

1go tool pprof http://localhost:6060/debug/pprof/heap?second=10
2

命令行 UI 查看方式同理

graph 中方框越大佔用內存越多火焰圖寬度越大佔用內存越多

SAMPLE->inuse_objects 可以查看當前的對象數量這個參數對於分析 gc 線程佔用較高 cpu 時很有用處它側重查看對象數量

inuse_space 圖可以查看具體的內存佔用

畢竟對於 10 個 100m 的對象和 1 億個 10 字節的對象佔用內存幾乎一樣大，但是回收起來一億個小對象肯定比 10 個大對象要慢很多。

1go tool pprof -inuse_space http://localhost:6060/debug/pprof/heap : 分析應用程序的常駐內存佔用情況 （默認）
2go tool pprof -alloc_objects http://localhost:6060/debug/pprof/heap: 分析應用程序的內存臨時分配情況
3

1.3 併發請求問題查看方式跟上面類似。

1go tool pprof http://localhost:6060/debug/pprof/goroutine
2go tool pprof http://localhost:6060/debug/pprof/block
3go tool pprof http://localhost:6060/debug/pprof/mutex
4

2.2 tracing

trace 並不是萬能的，它更側重於記錄分析採樣時間內運行時系統具體幹了什麼。

收集 trace 數據的三種方式:

使用 runtime/trace 包調用 trace.Start() 和 trace.Stop()
使用 go test -trace= 測試標識
使用 debug/pprof/trace handler 獲取運行時系統最好的方法

例如，通過

1go tool pprof http://localhost:6060/debug/pprof/trace?seconds=20 > trace.out
2

獲取運行時服務的 trace 信息，使用

1go tool trace trace.out
2

會自動打開瀏覽器展示出 UI 界面

其中 trace view 只能使用 chrome 瀏覽器查看，這裏 go 截止 1.14 版本存在一個 bug，解決辦法如下：

1go tool trace trace.out 無法查看trace view
2go bug:https://github.com/golang/go/issues/25151
3mac 解決版本：安裝gotip
4go get golang.org/dl/gotip
5gotip download
6then  使用 gotip tool trace trace.out即可
7

獲取的 trace.out 二進制文件也可以轉化爲 pprof 格式的文件

1go tool trace -pprof=TYPE trace.out > TYPE.pprof
2Tips:生成的profile文件 支持 network profiling、synchronization profiling、syscall profiling、scheduler profiling
3go tool pprof TYPE.pprof
4

ctrl + 1 選擇信息

ctrl + 3 放大選區

ctrl + 4 指定選區區間

shift + ? 幫助信息

AWSD 跟遊戲快捷鍵類似玩起來跟順手

整體的控制檯信息如下圖：

時間線: 顯示執行的時間單元根據時間的緯度不同可以調整區間
堆: 顯示執行期間內存的分配和釋放情況
協程 (Goroutine): 顯示每個時間點哪些 Goroutine 在運行哪些 goroutine 等待調度，其包含 GC 等待（GCWaiting）、可運行（Runnable）、運行中（Running）這三種狀態。

goroutine 區域選中時間區間

OS 線程 (Machine): 顯示在執行期間有多少個線程在運行，其包含正在調用 Syscall（InSyscall）、運行中（Running）這兩種狀態。

虛擬處理器 Processor: 每個虛擬處理器顯示一行，虛擬處理器的數量一般默認爲系統內核數。數量由環境變量 GOMAXPROCS 控制
協程和事件: 顯示在每個虛擬處理器上有什麼 Goroutine 正在運行，而連線行爲代表事件關聯。

每個 Processor 分兩層，上一層表示 Processor 上運行的 goroutine 的信息，下一層表示 processor 附加的事件比如 SysCall 或 runtime system events

ctrl+3 放大選區，選中 goroutine 可以查看，特定時間點特定 goroutine 的執行堆棧信息以及關聯的事件信息

goroutine analysis

點擊 goroutine 的 id 可以跳到 trace view 詳細查看 goroutine 具體幹了什麼

實踐一個延遲問題診斷

當我們一個執行關鍵任務的協程從運行中被阻塞。這裏可能的原因：被 syscall 阻塞、阻塞在共享內存 (channel/mutex etc)、阻塞在運行時 (如 GC)、甚至有可能是運行時調度器不工作導致的。這種問題使用 pprof 很難排查，

使用 trace 只要我們確定了時間範圍就可以在 proc 區域很容易找到問題的源頭

上圖可見，GC 的 MARK 階段阻塞了主協程的運行

2.3 GC

golang 的 gc 算法是根據標記清除改進的三色標記法，大概流程:

初始所有對象都是白色

Stack scan 階段: 從 root 出發掃描所有可達對象，標記爲灰色並放入待處理隊列；root 包括全局指針和 goroutine 棧上的指針
Mark 階段: 1. 從待處理隊列取出灰色對象，將其引用的對象標記爲灰色並放入隊列，自身標記爲黑色 2. re-scan 全局指針和棧，因爲 mark 和用戶程序並行運行，故過程 1 的時候可能會有新的對象分配，這時需要通過寫屏障 (write barrier) 記錄下來；re-scan 再完成檢查；
重複步驟 Mark 階段，直到灰色對象隊列爲空，執行清掃工作（白色即爲垃圾對象）

go 的三色標記法也存在 STW(Stop The World), 大致有兩個場景

GC 即將開始時，需要 STW 做一些準備工作，如 enable write barrier
re-scan 也需要 STW，否則上面 Mark 階段的 re-scan 無法終止

通過 GODEBUG=gctrace=1 可以開啓 gc 日誌，查看 gc 的結果信息

 1$ GODEBUG=gctrace=1 go run main.go   
 2gc 1 @0.001s 19%: 0.014+3.7+0.015 ms clock, 0.11+2.8/5.7/3.2+0.12 ms cpu, 5->6->6 MB, 6 MB goal, 8 P
 3gc 2 @0.024s 6%: 0.004+3.4+0.010 ms clock, 0.032+1.4/4.5/5.3+0.085 ms cpu, 13->14->13 MB, 14 MB goal, 8 P
 4gc 3 @0.093s 3%: 0.004+6.1+0.027 ms clock, 0.032+0.19/11/15+0.22 ms cpu, 24->25->22 MB, 26 MB goal, 8 P
 5scvg: 0 MB released
 6scvg: inuse: 4, idle: 58, sys: 63, released: 58, consumed: 4 (MB)
 7scvg: 0 MB released
 8scvg: inuse: 4, idle: 58, sys: 63, released: 58, consumed: 4 (MB)
 9scvg: 0 MB released
10scvg: inuse: 4, idle: 58, sys: 63, released: 58, consumed: 4 (MB)
11scvg: 0 MB released
12scvg: inuse: 4, idle: 58, sys: 63, released: 58, consumed: 4 (MB)
13

格式

gc # @#s #%: #+#+# ms clock, #+#/#/#+# ms cpu, #->#-># MB, # MB goal, # P

含義

gc#：GC 執行次數的編號，每次疊加。

@#s：自程序啓動後到當前的具體秒數。

#%：自程序啓動以來在 GC 中花費的時間百分比。

#+...+#：GC 的標記工作共使用的 CPU 時間佔總 CPU 時間的百分比。

#->#-># MB：分別表示 GC 啓動時, GC 結束時, GC 活動時的堆大小.

#MB goal：下一次觸發 GC 的內存佔用閾值。

#P：當前使用的處理器 P 的數量。

拓展

當我們的程序陷入 CPU 和 IO 混和負載過高時，我們使用 pprof profile 只能檢測出 CPU 耗時的函數，但是屏蔽了 IO 等待過長的函數。

https://github.com/felixge/fgprof 給出了一個解決方案：

具體做法是: 用一個後臺協程在採樣時間區間內每秒 99 次調用 runtime.GoruntineProfile，返回的結果忽略了協程當時消耗 CPU 還是非消耗 CPU 的區別進行統計，保存在內存中的 map 中，可導出轉化爲 pprof

具體用法：

 1package main
 2import(
 3    _ "net/http/pprof"
 4    "github.com/felixge/fgprof"
 5)
 6func main() {
 7    http.DefaultServeMux.Handle("/debug/fgprof", fgprof.Handler())
 8    go func() {
 9        log.Println(http.ListenAndServe(":6060", nil))
10    }()
11    // <code to profile>
12}
13git clone https://github.com/brendangregg/FlameGraph
14cd FlameGraph
15curl -s 'localhost:6060/debug/fgprof?seconds=3' > fgprof.fold
16./flamegraph.pl fgprof.fold > fgprof.svg
17

如果遇到這種 CPU 消耗型和非 CPU 消耗型混合的情況下可以試試排查下。

本文由 Readfog 進行 AMP 轉碼，版權歸原作者所有。
來源：https://mp.weixin.qq.com/s/yZUE8N-Qb-AB81DgA1cV_w?scene=25#wechat_redirect