go pprof與線上事故:一次成功的定位與失敗的復(fù)現(xiàn)

背景:一次大幾萬人的線上搶購活動(dòng)厘线,突然出現(xiàn)了問題识腿,頁面半天打不開,打開了半天下不了單皆的,cpu漲了又跌跌了又漲覆履,而內(nèi)存使用又穩(wěn)如老狗!不要慌费薄,按照套路去分析問題硝全,一切都不是問題!

閱讀此文你將收獲:

  • 分析問題的一個(gè)思路楞抡!
  • 學(xué)會(huì)使用pprof定位問題伟众。
  • 解決問題的一個(gè)思路!
大綱:
  1. 我是如何定位問題的
  2. 如何通過pprof精準(zhǔn)定位
  3. 通過pprof來定位代碼
  4. 我是如何trouble shooting

一. 我是如何思考問題的

“活動(dòng)掛了召廷,下不了單凳厢!”,隨著一聲凄涼的慘叫竞慢,辦公室大門被運(yùn)營人員打開先紫,于是活動(dòng)團(tuán)隊(duì)開始了緊張的bug定位過程。通過一段時(shí)間的代碼查看未能定位問題筹煮,重啟也沒法解決遮精。

通過finalshell上的機(jī)器使用率顯示,我們發(fā)現(xiàn)了一個(gè)有趣的現(xiàn)象,CPU的使用率從30%漲到60%再漲到99%本冲,然后又從10%開始一路往上漲准脂,如此往復(fù),但是內(nèi)存的使用率卻一動(dòng)不動(dòng)檬洞,非常穩(wěn)定狸膏。

為什么CPU會(huì)暴漲

CPU為什么這么奇怪?CPU是干什么的添怔?
CPU是負(fù)責(zé)計(jì)算的湾戳!

那么我們來猜測一下導(dǎo)致CPU暴漲的原因:

  1. 是某段代碼涉及計(jì)算量過大?
  2. 是小對(duì)象太多澎灸?導(dǎo)致GC壓力過大院塞?

然后導(dǎo)致cpu資源占用過高,在高并發(fā)環(huán)境下請(qǐng)求積壓越來越多性昭?處理不了拦止?

有了初步推測,下一步就該用出golang性能分析大殺器---pprof糜颠!

二. 如何用pproof精準(zhǔn)定位

很多小伙伴擔(dān)心線上使用pprof會(huì)影響性能汹族,擔(dān)心安全問題。這個(gè)在我看來利大于弊其兴,當(dāng)服務(wù)出現(xiàn)問題的時(shí)候顶瞒,資源占用多一點(diǎn)點(diǎn)與能夠解決問題相比微不足道,當(dāng)服務(wù)沒有問題的時(shí)候使用pprof那更沒有問題了~

在這里要推薦來自鵝廠大佬陳一梟在深圳gopher meetup上的分享:

《Go性能優(yōu)化之路》有詳細(xì)的PDF告訴你pprof以及性能優(yōu)化的各種細(xì)節(jié)元旬,更有教程demo讓你參考榴徐!
重點(diǎn)如下:
基準(zhǔn)---benchmark的使用
分析工具:GODEBUG
分析工具:go tool pprof
分析工具:go tool trace
PS:已經(jīng)與鳥哥溝通過,獲得使用許可

2.1 CPU Profile的使用

先期準(zhǔn)備:幾行代碼導(dǎo)入pprof

package main

import (
    "net/http"
    _ "net/http/pprof"
)

func main() {
    // 服務(wù)端啟動(dòng)一個(gè)協(xié)程匀归,支持pprof的handler
    //導(dǎo)入pprof的包坑资,自動(dòng)包含一些handler
    //項(xiàng)目加入如下代碼
    go func() {
        http.ListenAndServe("0.0.0.0:8888", nil)
    }()
    //other code
}
1.先看Graph圖

點(diǎn)擊view,選中g(shù)raph

該圖展示了函數(shù)邏輯調(diào)用樹穆端,框越紅袱贮,越大表示消耗越多!

直接將圖縮到最小

在該步驟中体啰,我們直接將graph圖縮到整個(gè)屏幕可見攒巍,哪里紅線明顯产阱,哪里框框最大当船,一目了然

通過縮略圖我們標(biāo)記了四個(gè)消耗量大的點(diǎn)位。我們?cè)倮^續(xù)看放大圖尘吗。

標(biāo)記點(diǎn)1
標(biāo)記2和標(biāo)記3
標(biāo)記4
選擇sample采樣
2.再看flame圖
flame圖SAMPLE中的cpu
  • 火焰圖中的X軸表示CPU耗時(shí)沽翔,越寬占用時(shí)間越多
  • Y軸表示函數(shù)棧調(diào)用深度常柄,尖刺越高表示函數(shù)棧調(diào)用越深

flame選中samples

我們可以看到其實(shí)采樣SAMPLE中選擇cpu或者samples都差不多,消耗越大的地方CPU占用越高搀擂,采樣點(diǎn)也是越集中在這里西潘!

3.再看Top
VIEW中選擇Top
  • Flat:函數(shù)自身運(yùn)行耗時(shí)
  • Flat%:函數(shù)自身耗時(shí)比例
  • Sum%:指的就是每一行的flat%與上面所有行的flat%總和
  • Cum:當(dāng)前函數(shù)加上它之上的調(diào)用運(yùn)行總耗時(shí)
  • Cum%:當(dāng)前函數(shù)加上它之上的調(diào)用運(yùn)行總耗時(shí)比例

舉例說明:函數(shù)b由三部分組成:調(diào)用函數(shù)c、自己直接處理一些事情哨颂、調(diào)用函數(shù)d喷市,其中調(diào)用函數(shù)c耗時(shí)1秒,自己直接處理事情耗時(shí)3秒威恼,調(diào)用函數(shù)d耗時(shí)2秒品姓,那么函數(shù)bflat耗時(shí)就是3秒,cum耗時(shí)就是6秒箫措。

// 該示例在文末參考列表的博客中
func b() {
    c() // takes 1s
    do something directly // takes 3s
    d() // takes 2s
}
4.看看內(nèi)存Profile
Graph_inuse_object
  • alloc_objects:收集自程序啟動(dòng)以來腹备,累計(jì)的分配對(duì)象數(shù)
  • alloc_space:收集自程序啟動(dòng)以來,累計(jì)的分配空間
  • inuse_objects:收集實(shí)時(shí)的正在使用的分配對(duì)象數(shù)
  • inuse_space:收集實(shí)時(shí)的正在使用的分配空間

如圖顯示這兩個(gè)地方使用對(duì)象最多斤蔓,分別占比53.10%與26.63%植酥,二者相加等于79.73%。
GC收集的就是內(nèi)存中的小對(duì)象弦牡,而這里我們所見的UnmarshalJSONjson compact所產(chǎn)生的對(duì)象占了80%友驮,這里可以列入優(yōu)化點(diǎn)!

三.通過pprof的定位來追代碼

通過pprofCPU與內(nèi)存的Graph驾锰、Flame GraphTop卸留,我們基本清楚了程序性能消耗大戶就在json.Unmarshal這一塊。下面我們通過針對(duì)第一個(gè)標(biāo)記點(diǎn)的分析椭豫,來示例如何查找問題代碼的耻瑟。

問題代碼函數(shù)調(diào)用鏈

從上圖可以分析出來是api.GetGiftCategoryDetails這個(gè)方法消耗了太多性能,因?yàn)橥伦呔褪?code>redis的HGetObjectjson的Unmarshal方法赏酥,這些方法屬于不可控方法喳整,不能直接對(duì)其進(jìn)行修改,所以定位就定位在api.GetGiftCategoryDetails這個(gè)方法上今缚!

func GetGiftCategoryDetails
上圖為pprof中標(biāo)記1的主要方法算柳,pprof cpu顯示,該方法消耗了大量的CPU時(shí)間姓言。
該方法被調(diào)用的時(shí)候會(huì)判斷in.Giftcategoryid是否有值瞬项,有值則從redis中取出數(shù)據(jù)。
進(jìn)入HGetObject方法何荚,如下圖:

HGetObject

繼續(xù)進(jìn)入decode方法囱淋!

decode

在該方法中我們看到了p.Option.Unmarshal,這個(gè)跟我們?cè)?code>pprof中看到的json Unmarshal是什么關(guān)系呢餐塘?
進(jìn)入p.Option.Unmarshal中查看妥衣。

Unmarshal

到這里就明白了默認(rèn)使用的是json.Unmarshal反序列化方法

那么我們從pprof中所觀察到的一切都能夠串聯(lián)起來了,整個(gè)邏輯流程如下:

調(diào)用流程

文章看到這里,在回頭看看pprofCPU還有其他的各種截圖税手,結(jié)合代碼蜂筹,整個(gè)流程清晰明了,就是從redis中取出數(shù)據(jù)的時(shí)候進(jìn)行的json.Unmarshal損耗CPU性能太多芦倒!

四. 我是如何trouble shooting的

既然我們知道了是json反序列化的問題導(dǎo)致這次線上事故的產(chǎn)生艺挪,那么這個(gè)問題我們?cè)撊绾谓鉀Q呢?


小case

這個(gè)很容易想到兵扬,既然標(biāo)準(zhǔn)庫中的json序列化效率不高麻裳,咱們換個(gè)高效率的不就行了嗎?例如:https://github.com/json-iterator/go

但是器钟,換了高效的json反序列化包津坑,那么效率到底能夠提升多少呢?30%傲霸?50%疆瑰,100%,三倍狞谱?五倍乃摹?十倍?···

我的看法是:脫離業(yè)務(wù)談技術(shù)的都是耍流氓跟衅!

事情并不簡單

在不清楚業(yè)務(wù)的情況下孵睬,任何解決方案都只是猜測而已,因?yàn)樽罡咝У氖侄斡肋h(yuǎn)都是從業(yè)務(wù)上去解決伶跷,然后再是技術(shù)手段掰读。

通過與活動(dòng)團(tuán)隊(duì)溝通,了解到業(yè)務(wù)邏輯如下:

  1. 近百萬用戶分為三個(gè)類別叭莫。
  2. 每個(gè)類別用戶進(jìn)入都會(huì)取出不同的商品列表蹈集。
  3. 商品列表存redis中。
  4. 每次從redis中取下來后反序列化返回給用戶端雇初。

那么看完了整個(gè)業(yè)務(wù)流程拢肆,應(yīng)該怎么去做呢?
咱們不妨從下面兩個(gè)角度想一想:

  • 技術(shù)角度(換json包)
  • 業(yè)務(wù)角度(利用本地緩存)

幾萬個(gè)用戶幾乎同時(shí)取redis中取三種相同的臃腫的數(shù)據(jù)靖诗,然后還需要經(jīng)過json反序列化去消耗大量的CPU郭怪,這樣做是否合理?

如果你覺得這樣不合理刊橘,那咱們換一個(gè)思路:
如果我們將這三類商品列表放在全局變量中鄙才,每次來了直接從全局變量中獲取這個(gè)方法怎么樣?(最簡單的一種辦法促绵,也可以使用多級(jí)存緩攒庵,具體根據(jù)團(tuán)隊(duì)情況取舍嘴纺,例如考慮一下代碼復(fù)雜度是否增加)

來,咱們算一算兩種方式的開銷如何:
1.redis走網(wǎng)絡(luò)開銷至少ms級(jí)浓冒,走內(nèi)存ns級(jí)栽渴,這里省了有沒有一萬或者八千倍

  1. 從內(nèi)存中取數(shù)據(jù)裆蒸,避免每次方法調(diào)用后對(duì)臨時(shí)變量的銷毀熔萧,還記得pprof標(biāo)記點(diǎn)4嗎?間接解決了GC壓力的問題
  2. 不需要經(jīng)過json序列化···掐指一算僚祷,省了···(不好意思,程序就卡死在這里贮缕,這里還有算的必要嗎辙谜?)

我們反思復(fù)盤一下,要是我們不考慮業(yè)務(wù)直接換json庫換上目前性能最高的json庫感昼,那么下次活動(dòng)結(jié)果會(huì)如何装哆?(心里知道就行了)

總結(jié):

1.談一談基礎(chǔ)

起碼得知道CPU是計(jì)算資源,查看CPU使用率和負(fù)載定嗓,當(dāng)CPU使用率低蜕琴,負(fù)載高是個(gè)什么情況。

又例如服務(wù)OOM了得考慮是不是內(nèi)存泄漏了宵溅,當(dāng)內(nèi)存泄漏的時(shí)候凌简,操作系統(tǒng)殺的一般是占用內(nèi)存最大的而不是泄露的···

2.了解分析工具的使用

常用的性能分析工具要掌握,pprof肯定不用說恃逻,還有一些Linux命令例如top雏搂,uptime,還有查看TCP連接數(shù)的等等命令寇损。

3.該如何解決問題

首先得分析問題凸郑,是CPU問題還是內(nèi)存問題,又或者是網(wǎng)絡(luò)問題矛市。當(dāng)三者都沒問題的時(shí)候芙沥,請(qǐng)你壓一壓是不是自己程序性能有問題···

當(dāng)能夠充分定位問題的時(shí)候,首先得梳理清楚業(yè)務(wù)流程浊吏,因?yàn)橐话阄覀冇玫陌蛘邩?biāo)準(zhǔn)庫而昨,亦或是框架,他們的性能相差其實(shí)也沒有大到很離譜卿捎,除非你故意挑個(gè)玩具代碼來應(yīng)用到生產(chǎn)環(huán)境配紫。

先確認(rèn)業(yè)務(wù)流程和程序處理上已經(jīng)沒有優(yōu)化的空間,請(qǐng)?jiān)倏紤]尋找一個(gè)高效的庫午阵,或者自己去實(shí)現(xiàn)一些代碼優(yōu)化措施躺孝!

PS:該業(yè)務(wù)不是我負(fù)責(zé)的享扔,純屬同事之間友情互助,幫忙查找問題植袍。至于后來我也模擬過同樣的數(shù)據(jù)惧眠,利用time.sleep(5ms)模擬從redis取數(shù)據(jù)的開銷,然后反序列化于个,但是并未出現(xiàn)CPU使用率波浪式呈現(xiàn)氛魁。太遺憾了,要是有知道的大佬還望不吝賜教厅篓!

感謝 阿郎秀存,孫偉,陳一梟等大佬提供的幫助
孫偉的GitHub:https://github.com/xiaowei520

參考資料與推薦閱讀文章:
滴滴實(shí)戰(zhàn)分享:通過 profiling 定位 golang 性能問題 - 內(nèi)存篇
Go語言性能優(yōu)化工具pprof文本輸出的含義
linux下查看cpu負(fù)載及分析

最后編輯于
?著作權(quán)歸作者所有,轉(zhuǎn)載或內(nèi)容合作請(qǐng)聯(lián)系作者
  • 序言:七十年代末羽氮,一起剝皮案震驚了整個(gè)濱河市或链,隨后出現(xiàn)的幾起案子,更是在濱河造成了極大的恐慌档押,老刑警劉巖澳盐,帶你破解...
    沈念sama閱讀 217,084評(píng)論 6 503
  • 序言:濱河連續(xù)發(fā)生了三起死亡事件,死亡現(xiàn)場離奇詭異令宿,居然都是意外死亡叼耙,警方通過查閱死者的電腦和手機(jī),發(fā)現(xiàn)死者居然都...
    沈念sama閱讀 92,623評(píng)論 3 392
  • 文/潘曉璐 我一進(jìn)店門粒没,熙熙樓的掌柜王于貴愁眉苦臉地迎上來筛婉,“玉大人,你說我怎么就攤上這事革娄∏惴。” “怎么了?”我有些...
    開封第一講書人閱讀 163,450評(píng)論 0 353
  • 文/不壞的土叔 我叫張陵拦惋,是天一觀的道長匆浙。 經(jīng)常有香客問我,道長厕妖,這世上最難降的妖魔是什么首尼? 我笑而不...
    開封第一講書人閱讀 58,322評(píng)論 1 293
  • 正文 為了忘掉前任,我火速辦了婚禮言秸,結(jié)果婚禮上软能,老公的妹妹穿的比我還像新娘。我一直安慰自己举畸,他們只是感情好查排,可當(dāng)我...
    茶點(diǎn)故事閱讀 67,370評(píng)論 6 390
  • 文/花漫 我一把揭開白布。 她就那樣靜靜地躺著抄沮,像睡著了一般跋核。 火紅的嫁衣襯著肌膚如雪岖瑰。 梳的紋絲不亂的頭發(fā)上,一...
    開封第一講書人閱讀 51,274評(píng)論 1 300
  • 那天砂代,我揣著相機(jī)與錄音蹋订,去河邊找鬼。 笑死刻伊,一個(gè)胖子當(dāng)著我的面吹牛露戒,可吹牛的內(nèi)容都是我干的。 我是一名探鬼主播捶箱,決...
    沈念sama閱讀 40,126評(píng)論 3 418
  • 文/蒼蘭香墨 我猛地睜開眼智什,長吁一口氣:“原來是場噩夢(mèng)啊……” “哼!你這毒婦竟也來了讼呢?” 一聲冷哼從身側(cè)響起撩鹿,我...
    開封第一講書人閱讀 38,980評(píng)論 0 275
  • 序言:老撾萬榮一對(duì)情侶失蹤,失蹤者是張志新(化名)和其女友劉穎悦屏,沒想到半個(gè)月后,有當(dāng)?shù)厝嗽跇淞掷锇l(fā)現(xiàn)了一具尸體键思,經(jīng)...
    沈念sama閱讀 45,414評(píng)論 1 313
  • 正文 獨(dú)居荒郊野嶺守林人離奇死亡础爬,尸身上長有42處帶血的膿包…… 初始之章·張勛 以下內(nèi)容為張勛視角 年9月15日...
    茶點(diǎn)故事閱讀 37,599評(píng)論 3 334
  • 正文 我和宋清朗相戀三年,在試婚紗的時(shí)候發(fā)現(xiàn)自己被綠了吼鳞。 大學(xué)時(shí)的朋友給我發(fā)了我未婚夫和他白月光在一起吃飯的照片看蚜。...
    茶點(diǎn)故事閱讀 39,773評(píng)論 1 348
  • 序言:一個(gè)原本活蹦亂跳的男人離奇死亡,死狀恐怖赔桌,靈堂內(nèi)的尸體忽然破棺而出供炎,到底是詐尸還是另有隱情,我是刑警寧澤疾党,帶...
    沈念sama閱讀 35,470評(píng)論 5 344
  • 正文 年R本政府宣布音诫,位于F島的核電站,受9級(jí)特大地震影響雪位,放射性物質(zhì)發(fā)生泄漏竭钝。R本人自食惡果不足惜,卻給世界環(huán)境...
    茶點(diǎn)故事閱讀 41,080評(píng)論 3 327
  • 文/蒙蒙 一雹洗、第九天 我趴在偏房一處隱蔽的房頂上張望香罐。 院中可真熱鬧,春花似錦时肿、人聲如沸庇茫。這莊子的主人今日做“春日...
    開封第一講書人閱讀 31,713評(píng)論 0 22
  • 文/蒼蘭香墨 我抬頭看了看天上的太陽旦签。三九已至查坪,卻和暖如春,著一層夾襖步出監(jiān)牢的瞬間顷霹,已是汗流浹背咪惠。 一陣腳步聲響...
    開封第一講書人閱讀 32,852評(píng)論 1 269
  • 我被黑心中介騙來泰國打工, 沒想到剛下飛機(jī)就差點(diǎn)兒被人妖公主榨干…… 1. 我叫王不留淋淀,地道東北人遥昧。 一個(gè)月前我還...
    沈念sama閱讀 47,865評(píng)論 2 370
  • 正文 我出身青樓,卻偏偏與公主長得像朵纷,于是被迫代替她去往敵國和親炭臭。 傳聞我的和親對(duì)象是個(gè)殘疾皇子,可洞房花燭夜當(dāng)晚...
    茶點(diǎn)故事閱讀 44,689評(píng)論 2 354