記一次獲得 3 倍性能的 go 程序優(yōu)化實(shí)踐羊娃,及 on-cpu / off-cpu 火焰圖的使用

轉(zhuǎn)自:https://mp.weixin.qq.com/s/9IKaXeWTiiQTFlvZzxgsEA

先把結(jié)論列在前面:

1.Golang的性能可以做到非常好拓春,但是一些native包的性能很可能會(huì)拖后腿纹磺,比如regexp和encoding/json弦聂。如果在性能要求較高的場(chǎng)合使用,要根據(jù)實(shí)際情況做相應(yīng)優(yōu)化柳击。

2.on-cpu/off-cpu火焰圖的使用是程序性能分析的利器猿推,往往一針見血。雖然生成一張火焰圖比較繁瑣(尤其是off-cpu圖)腻暮,但絕對(duì)值得擁有彤守!

之前一直使用Logstash作為日志文件采集客戶端程序毯侦。Logstash功能強(qiáng)大哭靖,有豐富的數(shù)據(jù)處理插件及很好的擴(kuò)展能力,但由于使用JRuby實(shí)現(xiàn)侈离,性能堪憂试幽。而Filebeat是后來出現(xiàn)的一個(gè)用go語(yǔ)言實(shí)現(xiàn)的,更輕量級(jí)的日志文件采集客戶端卦碾。性能不錯(cuò)铺坞、資源占用少,但幾乎沒有任何解析處理能力洲胖。通常的使用場(chǎng)景是使用Filebeat采集到Logstash解析處理济榨,然后再上傳到Kafka或Elasticsearch。值得注意的是绿映,Logstash和Filebeat都是Elastic公司的優(yōu)秀開源產(chǎn)品擒滑。

為了提高客戶端的日志采集性能腐晾,又減少數(shù)據(jù)傳輸環(huán)節(jié)和部署復(fù)雜度,并更充分的將go語(yǔ)言的性能優(yōu)勢(shì)利用于日志解析丐一,于是決定在Filebeat上通過開發(fā)插件的方式藻糖,實(shí)現(xiàn)針對(duì)公司日志格式規(guī)范的解析,直接作為L(zhǎng)ogstash的替代品库车。

背景介紹完畢巨柒,下面是實(shí)現(xiàn)和優(yōu)化的過程。

Version 1

先做一個(gè)最簡(jiǎn)單的實(shí)現(xiàn)柠衍,即用go自帶的正則表達(dá)式包regexp做日志解析洋满。性能已經(jīng)比Logstash(也是通過開發(fā)插件做規(guī)范日志解析)高出30%。

這里的性能測(cè)試著眼于日志采集的瓶頸——解析處理環(huán)節(jié)珍坊,指標(biāo)是在限制只使用一個(gè)cpu core的條件下(在服務(wù)器上要盡量減少對(duì)業(yè)務(wù)應(yīng)用的資源占用)芦岂,采集并解析1百萬條指定格式和長(zhǎng)度的日志所花費(fèi)的時(shí)間。測(cè)試環(huán)境是1臺(tái)主頻為3.2GHz的PC垫蛆。為了避免disk IO及page cache的影響禽最,將輸入文件和輸出文件都放在/dev/shm中。對(duì)于Filebeat的CPU限制袱饭,是通過啟動(dòng)時(shí)指定環(huán)境變量GOMAXPROCS=1實(shí)現(xiàn)川无。

這一版本處理1百萬條日志花費(fèi)的時(shí)間為122秒,即每秒8200條日志虑乖。

Version 2

接下來嘗試做一些優(yōu)化懦趋,看看這個(gè)go插件的性能還可不可以有些提升。首先想到的是替換regexp包疹味。Linux9下有一個(gè)C實(shí)現(xiàn)的PCRE庫(kù)仅叫,github.com/glenn-brown/golang-pkg-pcre/src/pkg/pcre這個(gè)第三方包正是將PCRE庫(kù)應(yīng)用到golang中。CentOS下需要先安裝pcre-devel這個(gè)包糙捺。
這個(gè)版本的處理時(shí)間為97秒诫咱,結(jié)果顯示比第一個(gè)版本的處理性能提升了25%。

Version 3

第三個(gè)版本洪灯,是完全不使用正則表達(dá)式坎缭,而是針對(duì)固定的日志格式規(guī)則,利用strings.Index()做字符串分解和提取操作签钩。這個(gè)版本的處理時(shí)間為70秒掏呼,性能又大大的提升了將近40%。

Version 4

那還有沒有進(jìn)一步提升的空間呢铅檩。有憎夷,就是Filebeat用作序列化輸出的json包。我們的日志上傳使用json格式昧旨,而Filebeat使用go自帶的encoding/json包是基于反射實(shí)現(xiàn)的拾给,性能一直廣受詬病富拗。如果對(duì)json解析有優(yōu)化的話,性能提高會(huì)是很可觀的鸣戴。既然我們的日志格式是固定的啃沪,解析出來的字段也是固定的,這時(shí)就可以基于固定的日志結(jié)構(gòu)體做json的序列化窄锅,而不必用低效率的反射來實(shí)現(xiàn)创千。go有多個(gè)針對(duì)給定結(jié)構(gòu)體做json序列化/反序列化的第三方包,我們這里使用的是easyjson(https://github.com/mailru/easyjson)入偷。在安裝完easyjson包后追驴,對(duì)我們包含了日志格式結(jié)構(gòu)體定義的程序文件執(zhí)行easyjson命令,會(huì)生成一個(gè)xxx_easyjson.go的文件疏之,里面包含了這個(gè)結(jié)構(gòu)體專用的Marshal/Unmarshal方法殿雪。這樣一來,處理時(shí)間又縮短為61秒锋爪,性能提高15%丙曙。

這時(shí),代碼在我面前其骄,已經(jīng)想不出有什么大的方面還可以優(yōu)化的了亏镰。是時(shí)候該本文的另一個(gè)主角,火焰圖出場(chǎng)了拯爽。

火焰圖是性能分析的一個(gè)有效工具索抓,這里(http://www.brendangregg.com/flamegraphs.html)是它的說明。通程号冢看到的火焰圖逼肯,是指on-cpu火焰圖,用來分析cpu都消耗在哪些函數(shù)調(diào)用上桃煎。

安裝完FlameGraph(https://github.com/brendangregg/FlameGraph)工具后篮幢,先對(duì)目前版本的程序運(yùn)行一次性能測(cè)試,按照說明抓取數(shù)據(jù)生成火焰圖如下备禀。

FlameGraph對(duì)于c/go程序是通用的洲拇。對(duì)于go程序奈揍,也可以使用自帶的net/http/pprof包作為數(shù)據(jù)源曲尸,然后安裝uber的go-torch(https://github.com/uber/go-torch)工具來自動(dòng)調(diào)用FlameGraph腳本生成on-cpu火焰圖,執(zhí)行會(huì)稍為簡(jiǎn)便一些男翰。參見go-torch說明另患。

圖中縱向代表的是函數(shù)調(diào)用棧,橫向各個(gè)方塊的寬度代表的是占用cpu時(shí)間的比例蛾绎,需要留意的是靠近頂端的大長(zhǎng)條昆箕。方塊的顏色是隨機(jī)的沒有實(shí)際意義液茎。

從上圖可以看到cpu時(shí)間占用最多的主要有兩塊盏阶。一塊是Output處理部分,稍為大頭的是json處理,這塊已經(jīng)優(yōu)化過沒什么可以做的了买窟。另一塊就比較奇怪了,是common.MapStr.Clone()方法铣口,居然占了40%的cpu時(shí)間笔呀。再往上看,主要是Errorf的處理捏题。一看代碼玻褪,馬上明白了。


common.MapStr是在pipeline中存放日志內(nèi)容的結(jié)構(gòu)體公荧,它的Clone()方法實(shí)現(xiàn)里判斷一個(gè)子鍵值是否為嵌套的Mapstr結(jié)構(gòu)時(shí)带射,是通過判斷toMapStr()方法是否返回error。從這里看循狰,生成error對(duì)象的代價(jià)是非晨呱纾可觀的。于是绪钥,一個(gè)顯然的fix桥爽,就是將toMapStr()中的判斷方法移到Clone()中并避免生成error。

Version 5

對(duì)修改后的代碼重新生成一張火焰圖如下昧识。

這時(shí)common.MapStr.Clone()從圖中已經(jīng)幾乎找不見了钠四,證明花費(fèi)的cpu時(shí)間已經(jīng)可以忽略不計(jì)。
測(cè)試時(shí)間一下子縮短到了46秒跪楞,節(jié)省了33%缀去,非常大的改善!

到現(xiàn)在甸祭,還有一個(gè)之前未提到的問題沒有解決——在限制使用一個(gè)core之后缕碎,測(cè)試運(yùn)行時(shí)cpu利用率只能跑到82%左右。是不是由于有鎖存在影響了性能呢池户?

這時(shí)候咏雌,又該請(qǐng)off-cpu火焰圖出場(chǎng)了。Off-cpu火焰圖校焦,是用來分析程序沒有有效利用cpu的時(shí)候赊抖,消耗在什么地方了,在這里(http://www.brendangregg.com/FlameGraphs/offcpuflamegraphs.html)有詳細(xì)的介紹寨典。數(shù)據(jù)收集比on-cpu火焰圖要復(fù)雜氛雪,可以使用大名鼎鼎的春哥提供的openresty-systemtap-toolkit(https://github.com/openresty/openresty-systemtap-toolkit)包。春哥的項(xiàng)目頁(yè)面中沒有詳細(xì)說明的是kernel-devel和debuginfo包的安裝方法耸成。在此也記錄一下报亩。

# kernel-devel沒有問題浴鸿,直接yum安裝
sudo yum install -y kernel-devel 

# debuginfo,在CentOS7中需要這樣裝
sudo vim /etc/yum.repos.d/CentOS-Debuginfo.repo

修改為enable=1
sudo debuginfo-install kernel

安裝時(shí)可能還會(huì)報(bào)錯(cuò):
Invalid GPG Key from file:///etc/pki/rpm-gpg/RPM-GPG-KEY-CentOS-Debug-7: No key found in given key data
需要從https://www.centos.org/keys/RPM-GPG-KEY-CentOS-Debug-7下載key寫入到/etc/pki/rpm-gpg/RPM-GPG-KEY-CentOS-Debug-7

安裝完后按照說明生成了off-cpu火焰圖如下:

我還不能完全解讀這張圖弦追,但是已經(jīng)可以明顯看到岳链,對(duì)Registry文件(Filebeat用于記錄文件采集列表和offset數(shù)據(jù))的寫操作占了一定比例。于是劲件,嘗試將Filebeat的spool_size(每完成這么多條日志更新一次Registry文件)設(shè)置為10240宠页,默認(rèn)值的5倍,運(yùn)行測(cè)試cpu已經(jīng)可以跑到95%以上寇仓。而將Registry設(shè)置到/dev/shm/下也同樣可以解決測(cè)試時(shí)cpu跑不滿的問題举户。

這就否定了上面對(duì)鎖使用不當(dāng)影響性能的猜測(cè)。在實(shí)際應(yīng)用時(shí)spool_size的設(shè)置應(yīng)當(dāng)依據(jù)結(jié)合了output端(如寫入到Kafka)的測(cè)試數(shù)據(jù)來決定遍烦。

至此俭嘁,優(yōu)化結(jié)束,達(dá)到了最初版本性能的3倍服猪!各個(gè)版本的具體運(yùn)行性能數(shù)據(jù)如下圖所示供填。

需要稍作說明的是:

1.Filebeat開發(fā)是基于5.3.1版本,go版本是1.8

2.Logstash的測(cè)試通過-w 1參數(shù)配置使用一個(gè)
工作進(jìn)程罢猪,并未限制使用一個(gè)core

3.執(zhí)行時(shí)間包括了程序的啟動(dòng)時(shí)間(Logstash的啟動(dòng)時(shí)間有將近20秒)

最終的優(yōu)化結(jié)果是近她,針對(duì)特定格式和長(zhǎng)度的日志解析能力在PC上達(dá)到了每秒25000條,即使在CPU主頻較低的生產(chǎn)服務(wù)器上膳帕,也可以達(dá)到每秒20000條粘捎。

最后編輯于
?著作權(quán)歸作者所有,轉(zhuǎn)載或內(nèi)容合作請(qǐng)聯(lián)系作者
  • 序言:七十年代末,一起剝皮案震驚了整個(gè)濱河市危彩,隨后出現(xiàn)的幾起案子攒磨,更是在濱河造成了極大的恐慌,老刑警劉巖汤徽,帶你破解...
    沈念sama閱讀 212,383評(píng)論 6 493
  • 序言:濱河連續(xù)發(fā)生了三起死亡事件娩缰,死亡現(xiàn)場(chǎng)離奇詭異,居然都是意外死亡谒府,警方通過查閱死者的電腦和手機(jī)拼坎,發(fā)現(xiàn)死者居然都...
    沈念sama閱讀 90,522評(píng)論 3 385
  • 文/潘曉璐 我一進(jìn)店門,熙熙樓的掌柜王于貴愁眉苦臉地迎上來完疫,“玉大人泰鸡,你說我怎么就攤上這事∏鞑遥” “怎么了鸟顺?”我有些...
    開封第一講書人閱讀 157,852評(píng)論 0 348
  • 文/不壞的土叔 我叫張陵,是天一觀的道長(zhǎng)器虾。 經(jīng)常有香客問我讯嫂,道長(zhǎng),這世上最難降的妖魔是什么兆沙? 我笑而不...
    開封第一講書人閱讀 56,621評(píng)論 1 284
  • 正文 為了忘掉前任欧芽,我火速辦了婚禮,結(jié)果婚禮上葛圃,老公的妹妹穿的比我還像新娘千扔。我一直安慰自己,他們只是感情好库正,可當(dāng)我...
    茶點(diǎn)故事閱讀 65,741評(píng)論 6 386
  • 文/花漫 我一把揭開白布曲楚。 她就那樣靜靜地躺著,像睡著了一般褥符。 火紅的嫁衣襯著肌膚如雪龙誊。 梳的紋絲不亂的頭發(fā)上,一...
    開封第一講書人閱讀 49,929評(píng)論 1 290
  • 那天喷楣,我揣著相機(jī)與錄音趟大,去河邊找鬼。 笑死铣焊,一個(gè)胖子當(dāng)著我的面吹牛逊朽,可吹牛的內(nèi)容都是我干的。 我是一名探鬼主播曲伊,決...
    沈念sama閱讀 39,076評(píng)論 3 410
  • 文/蒼蘭香墨 我猛地睜開眼叽讳,長(zhǎng)吁一口氣:“原來是場(chǎng)噩夢(mèng)啊……” “哼!你這毒婦竟也來了坟募?” 一聲冷哼從身側(cè)響起绽榛,我...
    開封第一講書人閱讀 37,803評(píng)論 0 268
  • 序言:老撾萬榮一對(duì)情侶失蹤,失蹤者是張志新(化名)和其女友劉穎婿屹,沒想到半個(gè)月后灭美,有當(dāng)?shù)厝嗽跇淞掷锇l(fā)現(xiàn)了一具尸體,經(jīng)...
    沈念sama閱讀 44,265評(píng)論 1 303
  • 正文 獨(dú)居荒郊野嶺守林人離奇死亡昂利,尸身上長(zhǎng)有42處帶血的膿包…… 初始之章·張勛 以下內(nèi)容為張勛視角 年9月15日...
    茶點(diǎn)故事閱讀 36,582評(píng)論 2 327
  • 正文 我和宋清朗相戀三年届腐,在試婚紗的時(shí)候發(fā)現(xiàn)自己被綠了。 大學(xué)時(shí)的朋友給我發(fā)了我未婚夫和他白月光在一起吃飯的照片蜂奸。...
    茶點(diǎn)故事閱讀 38,716評(píng)論 1 341
  • 序言:一個(gè)原本活蹦亂跳的男人離奇死亡犁苏,死狀恐怖,靈堂內(nèi)的尸體忽然破棺而出扩所,到底是詐尸還是另有隱情围详,我是刑警寧澤,帶...
    沈念sama閱讀 34,395評(píng)論 4 333
  • 正文 年R本政府宣布,位于F島的核電站助赞,受9級(jí)特大地震影響买羞,放射性物質(zhì)發(fā)生泄漏。R本人自食惡果不足惜雹食,卻給世界環(huán)境...
    茶點(diǎn)故事閱讀 40,039評(píng)論 3 316
  • 文/蒙蒙 一畜普、第九天 我趴在偏房一處隱蔽的房頂上張望。 院中可真熱鬧群叶,春花似錦吃挑、人聲如沸。這莊子的主人今日做“春日...
    開封第一講書人閱讀 30,798評(píng)論 0 21
  • 文/蒼蘭香墨 我抬頭看了看天上的太陽(yáng)。三九已至赎离,卻和暖如春逛犹,著一層夾襖步出監(jiān)牢的瞬間,已是汗流浹背蟹瘾。 一陣腳步聲響...
    開封第一講書人閱讀 32,027評(píng)論 1 266
  • 我被黑心中介騙來泰國(guó)打工圾浅, 沒想到剛下飛機(jī)就差點(diǎn)兒被人妖公主榨干…… 1. 我叫王不留,地道東北人憾朴。 一個(gè)月前我還...
    沈念sama閱讀 46,488評(píng)論 2 361
  • 正文 我出身青樓狸捕,卻偏偏與公主長(zhǎng)得像,于是被迫代替她去往敵國(guó)和親众雷。 傳聞我的和親對(duì)象是個(gè)殘疾皇子灸拍,可洞房花燭夜當(dāng)晚...
    茶點(diǎn)故事閱讀 43,612評(píng)論 2 350

推薦閱讀更多精彩內(nèi)容