golang 性能診斷看這篇就夠了

平均負(fù)載:0.14 0.07 0.06 分別表示過(guò)去1分鐘、5分鐘、15分鐘的機(jī)器負(fù)載的平均值，根據(jù)經(jīng)驗(yàn)，若負(fù)載數(shù)值小于0.7*CPU個(gè)數(shù)則正常，超過(guò)或者達(dá)到CPU核數(shù)的四五倍，則系統(tǒng)的負(fù)載就明顯偏高。

CPU的上下文切換情況可通過(guò)vmstat命令可以查看，上下文切換發(fā)生的場(chǎng)景有如下幾種:

1. 時(shí)間片用完，CPU正常調(diào)度下一個(gè)任務(wù)

2. 被其他優(yōu)先級(jí)更高的任務(wù)搶占

3. 執(zhí)行任務(wù)碰到I/O阻塞，掛起當(dāng)前任務(wù)，切換到下一個(gè)任務(wù)

4. 用戶(hù)代碼主動(dòng)掛起當(dāng)前任務(wù)讓出CPU

5. 多任務(wù)搶占資源，因沒(méi)搶到而被掛起

6. 硬件中斷
   

從操作系統(tǒng)角度，內(nèi)存關(guān)注應(yīng)用進(jìn)程是否足夠，可以使用 free –m 命令查看內(nèi)存的使用情況。

通過(guò) top 命令可以查看進(jìn)程使用的虛擬內(nèi)存 VIRT 和物理內(nèi)存 RES，根據(jù)公式 VIRT = SWAP + RES 可以推算出具體應(yīng)用使用的交換分區(qū)（Swap）情況，使用交換分區(qū)過(guò)大會(huì)影響 應(yīng)用性能，可以將 swappiness 值調(diào)到盡可能小。

I/O 包括磁盤(pán) I/O 和網(wǎng)絡(luò) I/O，一般情況下磁盤(pán)更容易出現(xiàn) I/O 瓶頸。通過(guò)iostat可以查看磁盤(pán)的讀寫(xiě)情況，通過(guò) CPU 的 I/O wait 可以看出磁盤(pán) I/O 是否正常。

如果磁盤(pán) I/O 一直處于很高的狀態(tài)，說(shuō)明磁盤(pán)太慢或故障，成為了性能瓶頸，需要進(jìn)行應(yīng)用優(yōu)化或者磁盤(pán)更換。

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

• Profiling 收集程序執(zhí)行過(guò)程中的具體事件，并抽樣統(tǒng)計(jì) 方便精確定位問(wèn)題

• Tracing 一種檢測(cè)代碼的方法，用于分析調(diào)用或用戶(hù)請(qǐng)求整個(gè)生命周期中的延遲，且可以跨多個(gè)Go進(jìn)程。

1.首先profiling代碼埋入

import _ "net/http/pprof"
func main() {    go func() {        log.Println(http.ListenAndServe("0.0.0.0:9090", nil))    }()    ...}

2.保存特定時(shí)間點(diǎn)的profile，例如保存heap信息

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

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

go tool pprof heap.tar.gz

pprof可以幫忙我們分析出函數(shù)執(zhí)行緩慢問(wèn)題??CPU占用過(guò)高問(wèn)題

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

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

top: 查看按照占用內(nèi)存或cpu多少排序的前10的函數(shù)信息

• flat:當(dāng)前函數(shù)占用的CPU時(shí)長(zhǎng)（不包含其調(diào)用的其他函數(shù)）

• flat%:當(dāng)前函數(shù)使用CPU占總CPU時(shí)長(zhǎng)的百分比

• sum%:前面每一行flat百分比的和

• cum: 累計(jì)量，當(dāng)前函數(shù)及其子函數(shù)占用CPU時(shí)長(zhǎng)?

• cum%:累計(jì)量占總量的百分比

? ? ? ?cum>=flat

list: 查看某個(gè)函數(shù)的代碼 以及該函數(shù)每行代碼的指標(biāo)信息

traces:打印所有函數(shù)調(diào)用棧 以及調(diào)用棧的指標(biāo)信息

UI界面方式：從服務(wù)器download下生成的sample文件??

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

Flame graph很清晰得可以看到當(dāng)前CPU被哪些函數(shù)執(zhí)行棧占用

1.2 Heap Profiling

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

命令行 UI查看方式 同理

graph中方框越大 占用內(nèi)存越多? 火焰圖 寬度越大 占用內(nèi)存越多

SAMPLE->inuse_objects可以查看當(dāng)前的對(duì)象數(shù)量 這個(gè)參數(shù)對(duì)于分析gc線程占用較高cpu時(shí)很有用處 它側(cè)重查看對(duì)象數(shù)量

inuse_space圖可以查看具體的內(nèi)存占用

畢竟對(duì)于10個(gè)100m的對(duì)象和1億個(gè)10字節(jié)的對(duì)象占用內(nèi)存幾乎一樣大，但是回收起來(lái)一億個(gè)小對(duì)象肯定比10個(gè)大對(duì)象要慢很多。

go tool pprof -inuse_space http://localhost:6060/debug/pprof/heap : 分析應(yīng)用程序的常駐內(nèi)存占用情況 （默認(rèn)）go tool pprof -alloc_objects http://localhost:6060/debug/pprof/heap: 分析應(yīng)用程序的內(nèi)存臨時(shí)分配情況

1.3 并發(fā)請(qǐng)求問(wèn)題 查看方式跟上面類(lèi)似。

go tool pprof http://localhost:6060/debug/pprof/goroutinego tool pprof http://localhost:6060/debug/pprof/blockgo tool pprof http://localhost:6060/debug/pprof/mutex

trace并不是萬(wàn)能的，它更側(cè)重于記錄分析 采樣時(shí)間內(nèi)運(yùn)行時(shí)系統(tǒng)具體干了什么。

收集trace數(shù)據(jù)的三種方式:

1. 使用runtime/trace包 調(diào)用trace.Start()和trace.Stop()

2. 使用go test -trace=測(cè)試標(biāo)識(shí)

3. 使用debug/pprof/trace handler 獲取運(yùn)行時(shí)系統(tǒng)最好的方法

例如，通過(guò)?

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

獲取運(yùn)行時(shí)服務(wù)的trace信息，使用

go tool trace trace.out

?會(huì)自動(dòng)打開(kāi)瀏覽器展示出UI界面

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

go tool trace trace.out 無(wú)法查看trace viewgo bug:https://github.com/golang/go/issues/25151mac 解決版本：安裝gotipgo get golang.org/dl/gotipgotip downloadthen  使用 gotip tool trace trace.out即可

獲取的trace.out 二進(jìn)制文件也可以轉(zhuǎn)化為pprof格式的文件

go tool trace -pprof=TYPE trace.out > TYPE.pprofTips:生成的profile文件 支持 network profiling、synchronization profiling、syscall profiling、scheduler profilinggo tool pprof TYPE.pprof

使用gotip tool trace trace.out可以查看到trace view的豐富操作界面：

操作技巧：

ctrl + 1? 選擇信息

ctrl + 2 移動(dòng)選區(qū)

ctrl + 3 放大選區(qū)

ctrl + 4 指定選區(qū)區(qū)間

shift + ? 幫助信息

AWSD跟游戲快捷鍵類(lèi)似 玩起來(lái)跟順手

整體的控制臺(tái)信息 如下圖：

• 時(shí)間線: 顯示執(zhí)行的時(shí)間單元 根據(jù)時(shí)間的緯度不同 可以調(diào)整區(qū)間

• 堆: 顯示執(zhí)行期間內(nèi)存的分配和釋放情況

• 協(xié)程(Goroutine): 顯示每個(gè)時(shí)間點(diǎn)哪些Goroutine在運(yùn)行 哪些goroutine等待調(diào)度 ，其包含 GC 等待（GCWaiting）、可運(yùn)行（Runnable）、運(yùn)行中（Running）這三種狀態(tài)。

goroutine區(qū)域選中時(shí)間區(qū)間

OS線程(Machine): 顯示在執(zhí)行期間有多少個(gè)線程在運(yùn)行，其包含正在調(diào)用 Syscall（InSyscall）、運(yùn)行中（Running）這兩種狀態(tài)。

• 虛擬處理器Processor: 每個(gè)虛擬處理器顯示一行，虛擬處理器的數(shù)量一般默認(rèn)為系統(tǒng)內(nèi)核數(shù)。數(shù)量由環(huán)境變量GOMAXPROCS控制

• 協(xié)程和事件: 顯示在每個(gè)虛擬處理器上有什么 Goroutine 正在運(yùn)行，而連線行為代表事件關(guān)聯(lián)。

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

ctrl+3 放大選區(qū)，選中g(shù)oroutine 可以查看，特定時(shí)間點(diǎn) 特定goroutine的執(zhí)行堆棧信息以及關(guān)聯(lián)的事件信息

goroutine analysis

點(diǎn)擊goroutine的id 可以跳到trace view 詳細(xì)查看goroutine具體干了什么

實(shí)踐 一個(gè)延遲問(wèn)題診斷

當(dāng)我們一個(gè)執(zhí)行關(guān)鍵任務(wù)的協(xié)程從運(yùn)行中被阻塞。這里可能的原因：被syscall阻塞 、阻塞在共享內(nèi)存(channel/mutex etc)、阻塞在運(yùn)行時(shí)(如 GC)、甚至有可能是運(yùn)行時(shí)調(diào)度器不工作導(dǎo)致的。這種問(wèn)題使用pprof很難排查，

使用trace只要我們確定了時(shí)間范圍就可以在proc區(qū)域很容易找到問(wèn)題的源頭

上圖可見(jiàn)，GC 的MARK階段阻塞了主協(xié)程的運(yùn)行

初始所有對(duì)象都是白色

1. Stack scan階段:從root出發(fā)掃描所有可達(dá)對(duì)象，標(biāo)記為灰色并放入待處理隊(duì)列；root包括全局指針和goroutine棧上的指針

2. Mark階段:1.從待處理隊(duì)列取出灰色對(duì)象，將其引用的對(duì)象標(biāo)記為灰色并放入隊(duì)列，自身標(biāo)記為黑色 2. re-scan全局指針和棧，因?yàn)閙ark和用戶(hù)程序并行運(yùn)行，故過(guò)程1的時(shí)候可能會(huì)有新的對(duì)象分配，這時(shí)需要通過(guò)寫(xiě)屏障(write barrier)記錄下來(lái)；re-scan再完成檢查；

3. 重復(fù)步驟Mark階段，直到灰色對(duì)象隊(duì)列為空，執(zhí)行清掃工作（白色即為垃圾對(duì)象）

1. GC即將開(kāi)始時(shí)，需要STW 做一些準(zhǔn)備工作， 如enable write barrier

2. re-scan也需要STW，否則上面Mark階段的re-scan無(wú)法終止

通過(guò)GODEBUG=gctrace=1可以開(kāi)啟gc日志，查看gc的結(jié)果信息

$ GODEBUG=gctrace=1 go run main.go   gc 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 Pgc 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 Pgc 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 Pscvg: 0 MB releasedscvg: inuse: 4, idle: 58, sys: 63, released: 58, consumed: 4 (MB)scvg: 0 MB releasedscvg: inuse: 4, idle: 58, sys: 63, released: 58, consumed: 4 (MB)scvg: 0 MB releasedscvg: inuse: 4, idle: 58, sys: 63, released: 58, consumed: 4 (MB)scvg: 0 MB releasedscvg: inuse: 4, idle: 58, sys: 63, released: 58, consumed: 4 (MB)

格式（不同版本可能會(huì)不同，具體參考 runtime 包的說(shuō)明）

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

含義

gc#：GC 執(zhí)行次數(shù)的編號(hào)，每次疊加。

@#s：自程序啟動(dòng)后到當(dāng)前的具體秒數(shù)。

#%：自程序啟動(dòng)以來(lái)在GC中花費(fèi)的時(shí)間百分比。

#+...+#：GC 的標(biāo)記工作共使用的 CPU 時(shí)間占總 CPU 時(shí)間的百分比。

#->#-># MB：分別表示 GC 啟動(dòng)時(shí), GC 結(jié)束時(shí), GC 活動(dòng)時(shí)的堆大小.

#MB goal：下一次觸發(fā) GC 的內(nèi)存占用閾值。

#P：當(dāng)前使用的處理器 P 的數(shù)量。

https://github.com/felixge/fgprof ?給出了一個(gè)解決方案：

具體用法：

package main import(    _ "net/http/pprof"    "github.com/felixge/fgprof") func main() {    http.DefaultServeMux.Handle("/debug/fgprof", fgprof.Handler())    go func() {        log.Println(http.ListenAndServe(":6060", nil))    }()     // } git clone https://github.com/brendangregg/FlameGraphcd FlameGraphcurl -s 'localhost:6060/debug/fgprof?seconds=3' > fgprof.fold./flamegraph.pl fgprof.fold > fgprof.svg

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

推薦閱讀


• 一文讀懂 Go profiling 和性能優(yōu)化