背景
最近上線了一個kafka的消費者，資料規模大概是低峰期單機每分鐘消費88W條，QPS 14666。上線後看了下資料，程序CPU到了132%。8核的機器，單程序CPU132倒也還好，但還是想看看，到底是咋回事。
過程
第一次排查&最佳化（協程池化->約為0最佳化）
於是就開始採集pprof的資料。golang pprof的採集是十分便捷的，在main.go引入net/http/pprof包，包裡pprof.go檔案的init()方法就會自動註冊相關的http路由。CPU的火焰圖看著就有點不合理，光是runtime的部分，居然耗費了1/3的CPU。首先懷疑是goroutine建立過多的問題，我們消費者框架如下圖，服務從kafka消費到一條msg後，會分發給每一個plugin，為了plugin之間互不影響，所以都是非同步呼叫plugin的。
所以這裡每條訊息會有放大的問題，這個服務有3個plugin，每條訊息就會建立3個goroutine，也就是每秒建立14666*3約45000 goroutine。解決辦法也簡單，就是池化，以達到goroutine複用的目的，也就是老生常談的協程池了。這裡用了我司的一位go社群大牛的協程池庫ants[1](可惜這位大牛已經江湖見了我哭死)，有協程池需求的可吃波安利。
👉點選領取Go後端開發資料合集
結果&問題
但上線後發現也就只有一點點效果，pprof再看了下goroutine的部分，取樣到的goroutine總數其實不多，這一步最佳化的前後的取樣也其實沒太大區別。而且想了下線上其他feed之類的服務，每個請求還併發拉多個資料來源來拼資料，那種服務的goroutine建立可猛多了，但也不會像我這個服務，光是GMP就佔了1/3。這一步最佳化，最終的結果就是，強行把框架的TODO完成了。。
第二次排查&最佳化（定時器“洩漏” -> 初見成效）
pprof看不出問題的話，就得考慮更多的效能分析工具了，於是開始用go trace，trace的路由是和pprof一同註冊的，直接使用就行。trace的用法要稍複雜點，用法可移步文末的參考文章，這裡就不貼了。在剛開始檢視問題時，不建議直接陷入goroutine排程的細節，因此一般先看 “Scheduler latency profile(排程延遲概況)”，能看到整體的呼叫開銷情況，如下：只能看到大部分的延遲是由select帶來的。。看不出個所以然，於是想把下面的幾個統計都先看看，結果看到Goroutine analysis時，發現了一個很怪異的資料。
Context居然執行過24W的goroutine。這裡有點要說明的，上文的圖三也是goroutine取樣資料, 路由是/debug/pprof/goroutine，個數是1000左右。而trace的Goroutine analysis，goroutine數 20W+了，數量級明顯不對。可以看下pprof.go對於前者的註釋，"goroutine": "Stack traces of all current goroutines", 顯然前者統計的是現有的所有goroutine；而後者法律時刻則是取樣期間所有執行過的goroutine。回到context那24W goroutine，追蹤程式碼看到是從這裡引入的，而time.AfterFunc()內部會使用goroutine
看到這裡，結合框架的程式碼就看出問題了。Context.WithDeadline()這個方法，會建立定時器，上面的註釋也給我們說了，當上下文完成時要立馬呼叫cancel來釋放資源。但框架裡用到這個函式的地方，只在err的時候立馬釋放了，正常情況的定時器，全都等到了執行時間執行，然後才釋放資源所以才有那麼多的goroutine執行。
大量的定時器排程，導致了GMP的排程需要很高的CPU，我是這麼理解的。解決問題的辦法更簡單了，呼叫完成後直接cancel()，如ctx, cancelFunc := context.WithTimeout(context.Background(), 5*time.Second)err := s.Limiter.Wait(ctx)if err != nil {log.Errorlnf("等待限流器錯誤，err:%v", err)cancelFunc()continue}ctxReadMsg, cancelFunc2 := context.WithTimeout(context.Background(), s.opt.FetchTimeout)msg, err := s.reader.ReadMessage(ctxReadMsg)if err != nil {if !errors.Is(err, context.DeadlineExceeded) {s.ErrorLogger.Printf("read message err:%v", err)}cancelFunc2()}
ctx, cancelFunc := context.WithTimeout(context.Background(), 5*time.Second)err := s.Limiter.Wait(ctx)if err != nil {log.Errorlnf("等待限流器錯誤，err:%v", err)cancelFunc()continue}cancelFunc()
結果&問題
上線後效果還是挺顯著的，CPU成功從132 下降到 100，最佳化了1/4。看新的trace，goroutine也沒了24W的大頭
但咋講呢。runtime的CPU 還是佔了很大一部分。。問題還是沒有徹底解決。排程的部分，還是有25%的CPU呼叫，加上sysmon的已經30%了。golang這麼優秀的語言，光是排程部分就這麼耗CPU也太不講道理了吧，肯定還有哪裡不對。
第三次排查&最佳化（GMP的自旋 -> 更進一層）
這次把pprof和trace裡所有的概況資料，以及具體的trace細節都看了，發現了有幾個疑惑點。-
排程延遲裡，大頭都是有阻塞的
-
View Trace的細節，每50ms，總會核心數的利用率大概只有50%的情況，8核，只用了4核（更貼切的說法是8個P，只有4個在處理G）
-
繼續細化View trace，發現即便在工作看著很密集的時候，大多數時間其實也只有1-2個P在同時Work。
這幾個點概括起來就是，1. 出現了較多的channel阻塞 2. P的使用率不高。於是到這裡就得引入我們的GMP模型了。首先是P，go為了讓新的G能儘快執行，所以會有一批P在不停自旋執行findrunnable，但自旋會耗費CPU啊，所以自旋的P也不能太多，而這個數是由GOMAXPROCS決定的，預設是CPU的核心數，我這裡是8核的機器，所以P數量是8。然後是阻塞，M關聯P執行後若遇到channel阻塞，P會和M解綁，然後P繼續找runnable的G。但我的服務是IO密集型，同一時間內大部分的G都在阻塞，所以能找到的也不多，同時有任務處理的P也不多。這兩個原因加起來就是，同時可執行的G不多，當前的P已經完全足夠了，導致剩下的P都在白白自旋。在網上的部落格中，也看到了類似的例子。解決方法就更簡單了，無非就是調低程式啟動的時候，把GOMAXPROCS調低。
func main() {runtime.GOMAXPROCS(4)// ...}
結果
終於cpu從100 下降到 73，火焰圖中，runtime排程的CPU佔比也降低了8。這裡其實還有一個點，對比圖10，runtime.sysmon的在火焰圖上看不到了，這裡後面再細化下原因。
總結
- golang 原生的pprof和trace支援，作為go開發者要熟練地用來做效能分析。
- 帶Deadline的Context，使用完記得及時回收資源。
- golang 的 GMP模型，P的數量，不是越多越好。