桔妹導(dǎo)讀：線上性能問題的定位和優(yōu)化是程序員進(jìn)階的必經(jīng)之路，定位問題的方式有多種多樣，常見的有觀察線程棧、排查日志和做性能分析。性能分析（profile）作為定位性能問題的大殺器，它可以收集程序執(zhí)行過程中的具體事件，并且對程序進(jìn)行抽樣統(tǒng)計(jì)，從而能更精準(zhǔn)的定位問題。本文會以 go 語言的 pprof 工具為例，分享兩個(gè)線上性能故障排查過程，希望能通過本文使大家對性能分析有更深入的理解。

在遇到線上的性能問題時(shí)，面對幾百個(gè)接口、成噸的日志，如何定位具體是哪里的代碼導(dǎo)致的問題呢？這篇文章會分享一下 profiling 這個(gè)定位性能問題的利器，內(nèi)容主要有：

• 如何通過做 profiling 來精準(zhǔn)定位故障源頭
• 兩個(gè)工作中通過 profiling 解決性能問題的實(shí)際例子
• 總結(jié)在做 profiling 時(shí)如何通過一些簡單的現(xiàn)象來快速定位問題的排查方向
• 日常 golang 編碼時(shí)要避開的一些坑
• 部分 golang 源碼解析

文章篇幅略長，也可直接翻到下面看經(jīng)驗(yàn)總結(jié)。

1.profiling是什么

profile 一般被稱為 性能分析，詞典上的翻譯是 概況（名詞）或者 描述…的概況（動詞）。對于計(jì)算機(jī)程序來說，它的 profile，就是一個(gè)程序在運(yùn)行時(shí)的各種概況信息，包括 cpu 占用情況，內(nèi)存情況，線程情況，線程阻塞情況等等。知道了程序的這些信息，也就能容易的定位程序中的問題和故障原因。

golang 對于 profiling 支持的比較好，標(biāo)準(zhǔn)庫就提供了profile庫 "runtime/pprof" 和 "net/http/pprof"，而且也提供了很多好用的可視化工具來輔助開發(fā)者做 profiling。

2.兩次 profiling 線上實(shí)戰(zhàn)

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

▍cpu 占用 99%

某天早上一到公司就收到了線上 cpu 占用率過高的報(bào)警。立即去看監(jiān)控，發(fā)現(xiàn)這個(gè)故障主要有下面四個(gè)特征：

• cpu idle 基本掉到了 0% ，內(nèi)存使用量有小幅度增長但不嚴(yán)重；
• 故障是偶發(fā)的，不是持續(xù)存在的；
• 故障發(fā)生時(shí)3臺機(jī)器的 cpu 幾乎是同時(shí)掉底；
• 故障發(fā)生后，兩個(gè)小時(shí)左右能恢復(fù)正常。

現(xiàn)象如圖，上為內(nèi)存，下為cpu idle：

檢查完監(jiān)控之后，立即又去檢查了一下有沒有影響線上業(yè)務(wù)。看了一下線上接口返回值和延遲，基本上還都能保持正常使用，就算cpu占用 99% 時(shí)接口延時(shí)也只比平常多了幾十ms。由于不影響線上業(yè)務(wù)，所以沒有選擇立即回滾，而是決定在線上定位問題（而且前一天后端也確實(shí)沒有上線新東西）。

所以給線上環(huán)境加上了 pprof，等著這個(gè)故障自己復(fù)現(xiàn)。代碼如下：

import _ "net/http/pprof"

func main() {
    go func() {
        log.Println(http.ListenAndServe("0.0.0.0:8005", nil))
    }()
    // ..... 下面業(yè)務(wù)代碼不用動
}

golang 對于 profiling 的支持比較完善，如代碼所示，只需要簡單的引入 "net/http/pprof" 這個(gè)包，然后在 main 函數(shù)里啟動一個(gè) http server 就相當(dāng)于給線上服務(wù)加上 profiling 了，通過訪問 8005 這個(gè) http 端口就可以對程序做采樣分析。

服務(wù)上開啟pprof之后，在本地電腦上使用 go tool pprof 命令，可以對線上程序發(fā)起采樣請求，golang pprof 工具會把采樣結(jié)果繪制成一個(gè)漂亮的前端頁面供人們排查問題。

等到故障再次復(fù)現(xiàn)時(shí)，我們首先對 cpu 性能進(jìn)行采樣分析：

brew install graphviz # 安裝graphviz，只需要安裝一次就行了

go tool pprof -http=:1234 http://your-prd-addr:8005/debug/pprof/profile?seconds=30 

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

分析此圖可以發(fā)現(xiàn)，cpu 資源的半壁江山都被 GetLeadCallRecordByLeadId 這個(gè)函數(shù)占用了，這個(gè)函數(shù)里占用 cpu 最多的又大多是數(shù)據(jù)庫訪問相關(guān)的函數(shù)調(diào)用。由于 GetLeadCallRecordByLeadId 此函數(shù)業(yè)務(wù)邏輯較為復(fù)雜，數(shù)據(jù)庫訪問較多，不太好具體排查是哪里出的問題，所以我把這個(gè)方向的排查先暫時(shí)擱置，把注意力放到了右邊那另外半壁江山。

在火焰圖的右邊，有個(gè)讓我比較在意的點(diǎn)是 runtime.gcBgMarkWorker 函數(shù)，這個(gè)函數(shù)是 golang 垃圾回收相關(guān)的函數(shù)，用于標(biāo)記（mark）出所有是垃圾的對象。一般情況下此函數(shù)不會占用這么多的 cpu，出現(xiàn)這種情況一般都是內(nèi)存 gc 問題，但是剛剛的監(jiān)控上看內(nèi)存占用只比平常多了幾百M(fèi)，并沒有特別高又是為什么呢？原因是影響GC性能的一般都不是內(nèi)存的占用量，而是對象的數(shù)量。舉例說明，10個(gè)100m的對象和一億個(gè)10字節(jié)的對象占用內(nèi)存幾乎一樣大，但是回收起來一億個(gè)小對象肯定會被10個(gè)大對象要慢很多。

插一段 golang 垃圾回收的知識，golang 使用“三色標(biāo)記法”作為垃圾回收算法，是“標(biāo)記-清除法”的一個(gè)改進(jìn)，相比“標(biāo)記-清除法”優(yōu)點(diǎn)在于它的標(biāo)記（mark）的過程是并發(fā)的，不會Stop The World。但缺點(diǎn)是對于巨量的小對象處理起來比較不擅長，有可能出現(xiàn)垃圾的產(chǎn)生速度比收集的速度還快的情況。gcMark線程占用高很大幾率就是對象產(chǎn)生速度大于垃圾回收速度了。

三色標(biāo)記法

所以轉(zhuǎn)換方向，又對內(nèi)存做了一下 profiling：

[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

然后在瀏覽器里點(diǎn)擊左上角 VIEW-》flame graph，然后點(diǎn)擊 SAMPLE-》inuse_objects。

這樣顯示的是當(dāng)前的對象數(shù)量：

可以看到，還是 GetLeadCallRecordByLeadId 這個(gè)函數(shù)的問題，它自己就產(chǎn)生了1億個(gè)對象，遠(yuǎn)超其他函數(shù)。所以下一步排查問題的方向確定了是：定位為何此函數(shù)產(chǎn)生了如此多的對象。

之后我開始在日志中 grep '/getLeadCallRecord' lead-platform. 來一點(diǎn)一點(diǎn)翻，重點(diǎn)看 cpu 掉底那個(gè)時(shí)刻附近的日志有沒有什么異常。果然發(fā)現(xiàn)了一條比較異常的日志：

[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 本應(yīng)該是一個(gè) int，但是前端給傳來一個(gè)JSON，推測應(yīng)該是前一天上線帶上去的bug。但是還有問題解釋不清楚，類型傳錯(cuò)應(yīng)該報(bào)錯(cuò)，但是為何會產(chǎn)生這么多對象呢？于是我進(jìn)代碼（已簡化）里看了看：

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"] = leadId
 conditions["bizType"] = bizType
 cond, val, err := builder.NamedQuery(sql, conditions)

發(fā)現(xiàn)很尷尬的是，這段遠(yuǎn)古代碼里對于 leadId 根本沒有判斷類型，直接用 string 了，前端傳什么過來都直接當(dāng)作 sql 參數(shù)了。也不知道為什么 MySQL 很抽風(fēng)的是，雖然 lead_id 字段類型是bigint，在 sql 里條件用 string 類型傳參數(shù) WHERE leadId = 'someString' 也能查到數(shù)據(jù)，而且返回的數(shù)據(jù)量很大。本身 lead_call_record 就是千萬級別的大表，這個(gè)查詢一下子返回了幾十萬條數(shù)據(jù)。又因?yàn)榇私涌诤罄m(xù)的查詢都是根據(jù)這個(gè)這個(gè)查詢返回的數(shù)據(jù)進(jìn)行查詢的，所以整個(gè)請求一下子就產(chǎn)生了上億個(gè)對象。

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

到此為止就終于定位到了問題所在，而且最一開始的四個(gè)現(xiàn)象也能解釋的通了：

• cpu idle 基本掉到了 0% ，內(nèi)存使用量有小幅度增長但不嚴(yán)重；
• 故障是偶發(fā)的，不是持續(xù)存在的；
• 故障發(fā)生時(shí)3臺機(jī)器的 cpu 幾乎是同時(shí)掉底；
• 故障發(fā)生后，兩個(gè)小時(shí)左右能恢復(fù)正常。

逐條解釋一下：

• GetLeadCallRecordByLeadId 函數(shù)每次在執(zhí)行時(shí)從數(shù)據(jù)庫取回的數(shù)據(jù)量過大，大量cpu時(shí)間浪費(fèi)在反序列化構(gòu)造對象 和 gc 回收對象上。
• 和前端確認(rèn) /lp-api/v2/leadCallRecord/getLeadCallRecord 接口并不是所有請求都會傳入json，只在某個(gè)頁面里才會有這種情況，所以故障是偶發(fā)的。
• 因?yàn)榻涌诓]有直接掛掉報(bào)錯(cuò)，而是執(zhí)行的很慢，所以應(yīng)用前面的負(fù)載均衡會超時(shí)，負(fù)載均衡器會把請求打到另一臺機(jī)器上，結(jié)果每次都會導(dǎo)致三臺機(jī)器同時(shí)爆表。
• 雖然申請了上億個(gè)對象，但 golang 的垃圾回收器是真滴靠譜，兢兢業(yè)業(yè)的回收了兩個(gè)多小時(shí)之后，就把幾億個(gè)對象全回收回去了，而且奇跡般的沒有影響線上業(yè)務(wù)。幾億個(gè)對象都扛得住，只能說厲害了我的go。

最后捋一下整個(gè)過程：

cpu占用99% -> 發(fā)現(xiàn)GC線程占用率持續(xù)異常 -> 懷疑是內(nèi)存問題 -> 排查對象數(shù)量 -> 定位產(chǎn)生對象異常多的接口 -> 定位到某接口 -> 在日志中找到此接口的異常請求 -> 根據(jù)異常參數(shù)排查代碼中的問題 -> 定位到問題

可以發(fā)現(xiàn)，有 pprof 工具在手的話，整個(gè)排查問題的過程都不會懵逼，基本上一直都照著正確的方向一步一步定位到問題根源。這就是用 profiling 的優(yōu)點(diǎn)所在。

▍內(nèi)存占用 90%

第二個(gè)例子是某天周會上有同學(xué)反饋說項(xiàng)目內(nèi)存占用達(dá)到了15個(gè)G之多，看了一下監(jiān)控現(xiàn)象如下：

• cpu占用并不高，最低idle也有85%
• 內(nèi)存占用呈鋸齒形持續(xù)上升，且速度很快，半個(gè)月就從2G達(dá)到了15G

如果所示：

鋸齒是因?yàn)闀円垢叻迤椒鍖?dǎo)致的暫時(shí)不用管，但持續(xù)上漲很明顯的是內(nèi)存泄漏的問題，有對象在持續(xù)產(chǎn)生，并且被持續(xù)引用著導(dǎo)致釋放不掉。于是上了 pprof 然后準(zhǔn)備等一晚上再排查，讓它先泄露一下再看現(xiàn)象會比較明顯。

這次重點(diǎn)看內(nèi)存的 inuse_space 圖，和 inuse_objects 圖不同的是，這個(gè)圖表示的是具體的內(nèi)存占用而不是對象數(shù)，然后VIEW類型也選graph，比火焰圖更清晰。

這個(gè)圖可以明顯的看出來程序中92%的對象都是由于 event.GetInstance 產(chǎn)生的。然后令人在意的點(diǎn)是這個(gè)函數(shù)產(chǎn)生的對象都是一個(gè)只有 16 個(gè)字節(jié)的對象（看圖上那個(gè)16B）這個(gè)是什么原因?qū)е碌暮竺鏁忉尅?/p>

先來看這個(gè)函數(shù)的代碼吧：

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

這個(gè)是做一個(gè)類似單例模式的功能，根據(jù)事件類型返回不同的 Handler。但是這個(gè)函數(shù)有問題的點(diǎn)有兩個(gè)：

• firstActivationEventHandler.ChildHandler 是一個(gè) interface，在給一個(gè) interface 賦值的時(shí)候，如果等號右邊是一個(gè) struct，會進(jìn)行值傳遞，也就意味著每次賦值都會在堆上復(fù)制一個(gè)此 struct 的副本。（golang默認(rèn)都是值傳遞）
• firstActivationEventHandler.ChildHandler = firstActivationEventHandler 是一個(gè)自己引用自己循環(huán)引用。

兩個(gè)問題導(dǎo)致了每次 GetInstance 函數(shù)在被調(diào)用的時(shí)候，都會復(fù)制一份之前的 firstActivationEventHandler 在堆上，并且讓 firstActivationEventHandler.ChildHandler 引用指向到這個(gè)副本上。

這就導(dǎo)致人為在內(nèi)存里創(chuàng)造了一個(gè)巨型的鏈表：

并且這個(gè)鏈表中所有節(jié)點(diǎn)都被之后的副本引用著，永遠(yuǎn)無法被GC當(dāng)作垃圾釋放掉。

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

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

另外，可以深究一下為什么都是一個(gè) 16B 的對象呢？為什么 interface 會復(fù)制呢？這里貼一下 golang runtime 關(guān)于 interface 部分的源碼：

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

// interface 底層定義
type iface struct {
    tab  *itab
    data unsafe.Pointer
}
// 空 interface 底層定義
type eface struct {
    _type *_type
    data  unsafe.Pointer
}
// 將某變量轉(zhuǎn)換為interface
func 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 這個(gè) struct 是 interface 在內(nèi)存中實(shí)際的布局。可以看到，在golang中定義一個(gè)interface，實(shí)際上在內(nèi)存中是一個(gè) tab 指針和一個(gè) data 指針，目前的機(jī)器都是64位的，一個(gè)指針占用8個(gè)字節(jié)，兩個(gè)就是16B。

我們的 firstActivationEventHandler 里面只有一個(gè) ChildHandler interface，所以整個(gè) firstActivationEventHandler 占用 16 個(gè)字節(jié)也就不奇怪了。

另外看代碼第 20 行那里，可以看到每次把變量轉(zhuǎn)為 interface 時(shí)是會做一次 mallocgc(t.size, t, true) 操作的，這個(gè)操作就會在堆上分配一個(gè)副本，第 21 行 typedmemmove(t, x, elem) 會進(jìn)行復(fù)制，會復(fù)制變量到堆上的副本上。這就解釋了開頭的問題。

3.經(jīng)驗(yàn)總結(jié)

在做內(nèi)存問題相關(guān)的 profiling 時(shí)：

• 若 gc 相關(guān)函數(shù)占用異常，可重點(diǎn)排查對象數(shù)量
• 解決速度問題（CPU占用）時(shí)，關(guān)注對象數(shù)量（ --inuse/alloc_objects ）指標(biāo)
• 解決內(nèi)存占用問題時(shí)，關(guān)注分配空間（ --inuse/alloc_space ）指標(biāo)
• inuse 代表當(dāng)前時(shí)刻的內(nèi)存情況，alloc 代表從從程序啟動到當(dāng)前時(shí)刻累計(jì)的內(nèi)存情況，一般情況下看 inuse 指標(biāo)更重要一些，但某些時(shí)候兩張圖對比著看也能有些意外發(fā)現(xiàn)。

在日常 golang 編碼時(shí)：

• 參數(shù)類型要檢查，尤其是 sql 參數(shù)要檢查（低級錯(cuò)誤）
• 傳遞struct盡量使用指針，減少復(fù)制和內(nèi)存占用消耗（尤其對于賦值給interface，會分配到堆上，額外增加gc消耗）
• 盡量不使用循環(huán)引用，除非邏輯真的需要
• 能在初始化中做的事就不要放到每次調(diào)用的時(shí)候做