https://www.infoq.cn/article/f69uvzjuomq276hbp1qb

線上效能問題的定位和優化是程式設計師進階的必經之路，定位問題的方式有多種多樣，常見的有觀察執行緒棧、排查日誌和做效能分析。效能分析（profile）作為定位效能問題的大殺器，它可以收集程式執行過程中的具體事件，並且對程式進行抽樣統計，從而能更精準的定位問題。本文會以 go 語言的 pprof 工具為例，分享兩個線上效能故障排查過程，希望能通過本文使大家對效能分析有更深入的理解。

在遇到線上的效能問題時，面對幾百個介面、成噸的日誌，如何定位具體是哪裡的程式碼導致的問題呢？這篇文章會分享一下 profiling 這個定位效能問題的利器，內容主要有：

• 如何通過做 profiling 來精準定位故障源頭

• 兩個工作中通過 profiling 解決效能問題的實際例子

• 總結在做 profiling 時如何通過一些簡單的現象來快速定位問題的排查方向

• 日常 golang 編碼時要避開的一些坑

• 部分 golang 原始碼解析

文章篇幅略長，也可直接翻到下面看經驗總結。

1.profiling 是什麼

profile 一般被稱為 效能分析，詞典上的翻譯是 概況（名詞）或者 描述…的概況（動詞）。對於計算機程式來說，它的 profile，就是一個程式在執行時的各種概況資訊，包括 cpu 佔用情況，記憶體情況，執行緒情況，執行緒阻塞情況等等。知道了程式的這些資訊，也就能容易的定位程式中的問題和故障原因。

golang 對於 profiling 支援的比較好，標準庫就提供了 profile 庫 “runtime/pprof” 和 “net/http/pprof”，而且也提供了很多好用的視覺化工具來輔助開發者做 profiling。

2.兩次 profiling 線上實戰

紙上得來終覺淺，下面分享兩個在工作中實際遇到的線上問題，以及我是如何通過 profiling 一步一步定位到問題的。

cpu 佔用 99%

某天早上一到公司就收到了線上 cpu 佔用率過高的報警。立即去看監控，發現這個故障主要有下面四個特徵：

• cpu idle 基本掉到了 0% ，記憶體使用量有小幅度增長但不嚴重；

• 故障是偶發的，不是持續存在的；

• 故障發生時 3 臺機器的 cpu 幾乎是同時掉底；

• 故障發生後，兩個小時左右能恢復正常。

現象如圖，上為記憶體，下為 cpu idle：

檢查完監控之後，立即又去檢查了一下有沒有影響線上業務。看了一下線上介面返回值和延遲，基本上還都能保持正常使用，就算 cpu 佔用 99% 時介面延時也只比平常多了幾十 ms。由於不影響線上業務，所以沒有選擇立即回滾，而是決定在線上定位問題（而且前一天後端也確實沒有上線新東西）。

所以給線上環境加上了 pprof，等著這個故障自己復現。程式碼如下：

import _ "net/http/pprof"
func main() {    go func() {        log.Println(http.ListenAndServe("0.0.0.0:8005", nil))    }()    // ..... 下面業務程式碼不用動}

複製程式碼

golang 對於 profiling 的支援比較完善，如程式碼所示，只需要簡單的引入 “net/http/pprof” 這個包，然後在 main 函式裡啟動一個 http server 就相當於給線上服務加上 profiling 了，通過訪問 8005 這個 http 埠就可以對程式做取樣分析。

服務上開啟 pprof 之後，在本地電腦上使用 go tool pprof 命令，可以對線上程式發起取樣請求，golang pprof 工具會把取樣結果繪製成一個漂亮的前端頁面供人們排查問題。

等到故障再次復現時，我們首先對 cpu 效能進行取樣分析：

brew install graphviz # 安裝graphviz，只需要安裝一次就行了
go tool pprof -http=:1234 http://your-prd-addr:8005/debug/pprof/profile?seconds=30 

複製程式碼

開啟 terminal，輸入上面命令，把命令中的 your-prd-addr 改成線上某臺機器的地址，然後回車等待 30 秒後，會自動在瀏覽器中開啟一個頁面，這個頁面包含了剛剛 30 秒內對線上 cpu 佔用情況的一個概要分析。點選左上角的 View 選擇 Flame graph，會用火焰圖（Flame graph）來顯示 cpu 的佔用情況：

分析此圖可以發現，cpu 資源的半壁江山都被 GetLeadCallRecordByLeadId 這個函式佔用了，這個函式裡佔用 cpu 最多的又大多是資料庫訪問相關的函式呼叫。由於 GetLeadCallRecordByLeadId 此函式業務邏輯較為複雜，資料庫訪問較多，不太好具體排查是哪裡出的問題，所以我把這個方向的排查先暫時擱置，把注意力放到了右邊那另外半壁江山。

在火焰圖的右邊，有個讓我比較在意的點是 runtime.gcBgMarkWorker 函式，這個函式是 golang 垃圾回收相關的函式，用於標記（mark）出所有是垃圾的物件。一般情況下此函式不會佔用這麼多的 cpu，出現這種情況一般都是記憶體 gc 問題，但是剛剛的監控上看記憶體佔用只比平常多了幾百 M，並沒有特別高又是為什麼呢？原因是影響 GC 效能的一般都不是記憶體的佔用量，而是物件的數量。舉例說明，10 個 100m 的物件和一億個 10 位元組的物件佔用記憶體幾乎一樣大，但是回收起來一億個小物件肯定會被 10 個大物件要慢很多。

插一段 golang 垃圾回收的知識，golang 使用“三色標記法”作為垃圾回收演算法，是“標記-清除法”的一個改進，相比“標記-清除法”優點在於它的標記（mark）的過程是併發的，不會 Stop The World。但缺點是對於巨量的小物件處理起來比較不擅長，有可能出現垃圾的產生速度比收集的速度還快的情況。gcMark 執行緒佔用高很大機率就是物件產生速度大於垃圾回收速度了。

三色標記法

所以轉換方向，又對記憶體做了一下 profiling：

go tool pprof http://your-prd-addr:8005/debug/pprof/heap 

複製程式碼

然後在瀏覽器裡點選左上角 VIEW-》flame graph，然後點選 SAMPLE-》inuse_objects。

這樣顯示的是當前的物件數量：

可以看到，還是 GetLeadCallRecordByLeadId 這個函式的問題，它自己就產生了 1 億個物件，遠超其他函式。所以下一步排查問題的方向確定了是：定位為何此函式產生了如此多的物件。

之後我開始在日誌中 grep ‘/getLeadCallRecord’ lead-platform. 來一點一點翻，重點看 cpu 掉底那個時刻附近的日誌有沒有什麼異常。果然發現了一條比較異常的日誌：

[net/http.HandlerFunc.ServeHTTP/server.go:1947] _com_request_in||traceid=091d682895eda2fsdffsd0cbe3f9a95||spanid=297b2a9sdfsdfsdfb8bf739||hintCode=||hintContent=||method=GET||host=10.88.128.40:8000||uri=/lp-api/v2/leadCallRecord/getLeadCallRecord||params=leadId={"id":123123}||from=10.0.0.0||proto=HTTP/1.0

複製程式碼

注意看 params 那裡，leadId 本應該是一個 int，但是前端給傳來一個 JSON，推測應該是前一天上線帶上去的 bug。但是還有問題解釋不清楚，型別傳錯應該報錯，但是為何會產生這麼多物件呢？於是我進程式碼（已簡化）裡看了看：

func GetLeadCallRecord(leadId string, bizType int) ([]model.LeadCallRecords, error) {sql := "SELECT record.* FROM lead_call_record AS record " +"where record.lead_id  = {{leadId}} and record.biz_type = {{bizType}}"conditions := make(map[string]interface{}, 2)conditions["leadId"] = leadIdconditions["bizType"] = bizTypecond, val, err := builder.NamedQuery(sql, conditions)

複製程式碼

發現很尷尬的是，這段遠古程式碼裡對於 leadId 根本沒有判斷型別，直接用 string 了，前端傳什麼過來都直接當作 sql 引數了。也不知道為什麼 mysql 很抽風的是，雖然 lead_id 欄位型別是 bigint，在 sql 裡條件用 string 型別傳引數 WHERE leadId = ‘someString’ 也能查到資料，而且返回的資料量很大。本身 lead_call_record 就是千萬級別的大表，這個查詢一下子返回了幾十萬條資料。又因為此介面後續的查詢都是根據這個這個查詢返回的資料進行查詢的，所以整個請求一下子就產生了上億個物件。

由於之前傳參都是正確的，所以一直沒有觸發這個問題，正好前一天前端小姐姐上線需求帶上了這個 bug，一波前後端混合雙打造成了這次故障。

到此為止就終於定位到了問題所在，而且最一開始的四個現象也能解釋的通了：

• cpu idle 基本掉到了 0% ，記憶體使用量有小幅度增長但不嚴重；

• 故障是偶發的，不是持續存在的；

• 故障發生時 3 臺機器的 cpu 幾乎是同時掉底；

• 故障發生後，兩個小時左右能恢復正常。

逐條解釋一下：

• GetLeadCallRecordByLeadId 函式每次在執行時從資料庫取回的資料量過大，大量 cpu 時間浪費在反序列化構造物件 和 gc 回收物件上。

• 和前端確認 /lp-api/v2/leadCallRecord/getLeadCallRecord 介面並不是所有請求都會傳入 json，只在某個頁面裡才會有這種情況，所以故障是偶發的。

• 因為介面並沒有直接掛掉報錯，而是執行的很慢，所以應用前面的負載均衡會超時，負載均衡器會把請求打到另一臺機器上，結果每次都會導致三臺機器同時爆表。

• 雖然申請了上億個物件，但 golang 的垃圾回收器是真滴靠譜，兢兢業業的回收了兩個多小時之後，就把幾億個物件全回收回去了，而且奇蹟般的沒有影響線上業務。幾億個物件都扛得住，只能說厲害了我的 go。

最後捋一下整個過程：

cpu 佔用 99% -> 發現 GC 執行緒佔用率持續異常 -> 懷疑是記憶體問題 -> 排查物件數量 -> 定位產生物件異常多的介面 -> 定位到某介面 -> 在日誌中找到此介面的異常請求 -> 根據異常引數排查程式碼中的問題 -> 定位到問題

可以發現，有 pprof 工具在手的話，整個排查問題的過程都不會懵逼，基本上一直都照著正確的方向一步一步定位到問題根源。這就是用 profiling 的優點所在。

記憶體佔用 90%

第二個例子是某天週會上有同學反饋說專案記憶體佔用達到了 15 個 G 之多，看了一下監控現象如下：

• cpu 佔用並不高，最低 idle 也有 85%

• 記憶體佔用呈鋸齒形持續上升，且速度很快，半個月就從 2G 達到了 15G

如果所示：

鋸齒是因為晝夜高峰平峰導致的暫時不用管，但持續上漲很明顯的是記憶體洩漏的問題，有物件在持續產生，並且被持續引用著導致釋放不掉。於是上了 pprof 然後準備等一晚上再排查，讓它先洩露一下再看現象會比較明顯。

這次重點看記憶體的 inuse_space 圖，和 inuse_objects 圖不同的是，這個圖表示的是具體的記憶體佔用而不是物件數，然後 VIEW 型別也選 graph，比火焰圖更清晰。

這個圖可以明顯的看出來程式中 92%的物件都是由於 event.GetInstance 產生的。然後令人在意的點是這個函式產生的物件都是一個只有 16 個位元組的物件（看圖上那個 16B）這個是什麼原因導致的後面會解釋。

先來看這個函式的程式碼吧：

var (    firstActivationEventHandler FirstActivationEventHandler    firstOnlineEventHandler FirstOnlineEventHandler)func GetInstance(eventType string) Handler {    if eventType == FirstActivation {        firstActivationEventHandler.ChildHandler = firstActivationEventHandlerreturn firstActivationEventHandler    } else if eventType == FirstOnline {        firstOnlineEventHandler.ChildHandler = firstOnlineEventHandlerreturn firstOnlineEventHandler}// ... 各種類似的判斷，略過    return nil}

複製程式碼

這個是做一個類似單例模式的功能，根據事件型別返回不同的 Handler。但是這個函式有問題的點有兩個：

• firstActivationEventHandler.ChildHandler 是一個 interface，在給一個 interface 賦值的時候，如果等號右邊是一個 struct，會進行值傳遞，也就意味著每次賦值都會在堆上覆制一個此 struct 的副本。（golang 預設都是值傳遞）

• firstActivationEventHandler.ChildHandler = firstActivationEventHandler 是一個自己引用自己迴圈引用。

兩個問題導致了每次 GetInstance 函式在被呼叫的時候，都會複製一份之前的 firstActivationEventHandler 在堆上，並且讓 firstActivationEventHandler.ChildHandler 引用指向到這個副本上。

這就導致人為在記憶體裡創造了一個巨型的連結串列：

並且這個連結串列中所有節點都被之後的副本引用著，永遠無法被 GC 當作垃圾釋放掉。

所以解決這個問題方案也很簡單，單例模式只需要在 init 函式裡初始化一次就夠了，沒必要在每次 GetInstance 的時候做初始化操作：

func init() {    firstActivationEventHandler.ChildHandler = &firstActivationEventHandler    firstOnlineEventHandler.ChildHandler = &firstOnlineEventHandler// ... 略過}

複製程式碼

另外，可以深究一下為什麼都是一個 16B 的物件呢？為什麼 interface 會複製呢？這裡貼一下 golang runtime 關於 interface 部分的原始碼：

下面分析 golang 原始碼，不感興趣可直接略過。

// interface 底層定義type iface struct {    tab  *itab    data unsafe.Pointer}// 空 interface 底層定義type eface struct {    _type *_type    data  unsafe.Pointer}// 將某變數轉換為interfacefunc convT2I(tab *itab, elem unsafe.Pointer) (i iface) {    t := tab._type    if raceenabled {        raceReadObjectPC(t, elem, getcallerpc(), funcPC(convT2I))    }    if msanenabled {        msanread(elem, t.size)    }    x := mallocgc(t.size, t, true)    typedmemmove(t, x, elem)    i.tab = tab    i.data = x    return}

複製程式碼

iface 這個 struct 是 interface 在記憶體中實際的佈局。可以看到，在 golang 中定義一個 interface，實際上在記憶體中是一個 tab 指標和一個 data 指標，目前的機器都是 64 位的，一個指標佔用 8 個位元組，兩個就是 16B。

我們的 firstActivationEventHandler 裡面只有一個 ChildHandler interface，所以整個 firstActivationEventHandler 佔用 16 個位元組也就不奇怪了。

另外看程式碼第 20 行那裡，可以看到每次把變數轉為 interface 時是會做一次 mallocgc(t.size, t, true) 操作的，這個操作就會在堆上分配一個副本，第 21 行 typedmemmove(t, x, elem) 會進行復制，會複製變數到堆上的副本上。這就解釋了開頭的問題。

3.經驗總結

在做記憶體問題相關的 profiling 時：

• 若 gc 相關函式佔用異常，可重點排查物件數量

• 解決速度問題（CPU 佔用）時，關注物件數量（ --inuse/alloc_objects ）指標

• 解決記憶體佔用問題時，關注分配空間（ --inuse/alloc_space ）指標

inuse 代表當前時刻的記憶體情況，alloc 代表從從程式啟動到當前時刻累計的記憶體情況，一般情況下看 inuse 指標更重要一些，但某些時候兩張圖對比著看也能有些意外發現。

在日常 golang 編碼時：

• 引數型別要檢查，尤其是 sql 引數要檢查（低階錯誤）

• 傳遞 struct 儘量使用指標，減少複製和記憶體佔用消耗（尤其對於賦值給 interface，會分配到堆上，額外增加 gc 消耗）

• 儘量不使用迴圈引用，除非邏輯真的需要

• 能在初始化中做的事就不要放到每次呼叫的時候做