記一次得到 3 倍性能的 go 程序優化實踐，及 on-cpu / off-cpu 火焰圖的使用

轉自：https://mp.weixin.qq.com/s/9IKaXeWTiiQTFlvZzxgsEA

 

記一次得到 3 倍性能的 go 程序優化實踐，及 on-cpu / off-cpu 火焰圖的使用

原創 2017-07-27 petergz 惟技術

先把結論列在前面：

1.Golang的性能能夠作到很是好，可是一些native包的性能極可能會拖後腿，好比regexp和encoding/json。若是在性能要求較高的場合使用，要根據實際狀況作相應優化。

 

2.on-cpu/off-cpu火焰圖的使用是程序性能分析的利器，每每一針見血。雖然生成一張火焰圖比較繁瑣（尤爲是off-cpu圖），但絕對值得擁有！

 

以前一直使用Logstash做爲日誌文件採集客戶端程序。Logstash功能強大，有豐富的數據處理插件及很好的擴展能力，但因爲使用JRuby實現，性能堪憂。而Filebeat是後來出現的一個用go語言實現的，更輕量級的日誌文件採集客戶端。性能不錯、資源佔用少，但幾乎沒有任何解析處理能力。一般的使用場景是使用Filebeat採集到Logstash解析處理，而後再上傳到Kafka或Elasticsearch。值得注意的是，Logstash和Filebeat都是Elastic公司的優秀開源產品。

 

爲了提升客戶端的日誌採集性能，又減小數據傳輸環節和部署複雜度，並更充分的將go語言的性能優點利用於日誌解析，因而決定在Filebeat上經過開發插件的方式，實現針對公司日誌格式規範的解析，直接做爲Logstash的替代品。

 

背景介紹完畢，下面是實現和優化的過程。

 

Version 1

先作一個最簡單的實現，即用go自帶的正則表達式包regexp作日誌解析。性能已經比Logstash（也是經過開發插件作規範日誌解析）高出30%。

 

這裏的性能測試着眼於日誌採集的瓶頸——解析處理環節，指標是在限制只使用一個cpu core的條件下（在服務器上要儘可能減小對業務應用的資源佔用），採集並解析1百萬條指定格式和長度的日誌所花費的時間。測試環境是1臺主頻爲3.2GHz的PC。爲了不disk IO及page cache的影響，將輸入文件和輸出文件都放在/dev/shm中。對於Filebeat的CPU限制，是經過啓動時指定環境變量GOMAXPROCS=1實現。

 

這一版本處理1百萬條日誌花費的時間爲122秒，即每秒8200條日誌。

 

Version 2

接下來嘗試作一些優化，看看這個go插件的性能還可不能夠有些提高。首先想到的是替換regexp包。Linux9下有一個C實現的PCRE庫，github.com/glenn-brown/golang-pkg-pcre/src/pkg/pcre這個第三方包正是將PCRE庫應用到golang中。CentOS下須要先安裝pcre-devel這個包。

這個版本的處理時間爲97秒，結果顯示比第一個版本的處理性能提高了25%。

 

Version 3

第三個版本，是徹底不使用正則表達式，而是針對固定的日誌格式規則，利用strings.Index()作字符串分解和提取操做。這個版本的處理時間爲70秒，性能又大大的提高了將近40%。

 

Version 4

那還有沒有進一步提高的空間呢。有，就是Filebeat用做序列化輸出的json包。咱們的日誌上傳使用json格式，而Filebeat使用go自帶的encoding/json包是基於反射實現的，性能一直廣受詬病。若是對json解析有優化的話，性能提升會是很可觀的。既然咱們的日誌格式是固定的，解析出來的字段也是固定的，這時就能夠基於固定的日誌結構體作json的序列化，而沒必要用低效率的反射來實現。go有多個針對給定結構體作json序列化/反序列化的第三方包，咱們這裏使用的是easyjson（https://github.com/mailru/easyjson）。在安裝完easyjson包後，對咱們包含了日誌格式結構體定義的程序文件執行easyjson命令，會生成一個xxx_easyjson.go的文件，裏面包含了這個結構體專用的Marshal/Unmarshal方法。這樣一來，處理時間又縮短爲61秒，性能提升15%。

 

這時，代碼在我面前，已經想不出有什麼大的方面還能夠優化的了。是時候該本文的另外一個主角，火焰圖出場了。

 

 

火焰圖是性能分析的一個有效工具，這裏（http://www.brendangregg.com/flamegraphs.html）是它的說明。一般看到的火焰圖，是指on-cpu火焰圖，用來分析cpu都消耗在哪些函數調用上。

 

安裝完FlameGraph（https://github.com/brendangregg/FlameGraph）工具後，先對目前版本的程序運行一次性能測試，按照說明抓取數據生成火焰圖以下。

 

FlameGraph對於c/go程序是通用的。對於go程序，也可使用自帶的net/http/pprof包做爲數據源，而後安裝uber的go-torch（https://github.com/uber/go-torch）工具來自動調用FlameGraph腳本生成on-cpu火焰圖，執行會稍爲簡便一些。參見go-torch說明。

 

 

圖中縱向表明的是函數調用棧，橫向各個方塊的寬度表明的是佔用cpu時間的比例，須要留意的是靠近頂端的大長條。方塊的顏色是隨機的沒有實際意義。

 

從上圖能夠看到cpu時間佔用最多的主要有兩塊。一塊是Output處理部分，稍爲大頭的是json處理，這塊已經優化過沒什麼能夠作的了。另外一塊就比較奇怪了，是common.MapStr.Clone()方法，竟然佔了40%的cpu時間。再往上看，主要是Errorf的處理。一看代碼，立刻明白了。

common.MapStr是在pipeline中存放日誌內容的結構體，它的Clone()方法實現裏判斷一個子鍵值是否爲嵌套的Mapstr結構時，是經過判斷toMapStr()方法是否返回error。從這裏看，生成error對象的代價是很是可觀的。因而，一個顯然的fix，就是將toMapStr()中的判斷方法移到Clone()中並避免生成error。

 

Version 5

對修改後的代碼從新生成一張火焰圖以下。

 

 

這時common.MapStr.Clone()從圖中已經幾乎找不見了，證實花費的cpu時間已經能夠忽略不計。

測試時間一會兒縮短到了46秒，節省了33%，很是大的改善！

 

 

到如今，還有一個以前未提到的問題沒有解決——在限制使用一個core以後，測試運行時cpu利用率只能跑到82%左右。是否是因爲有鎖存在影響了性能呢？

 

這時候，又該請off-cpu火焰圖出場了。Off-cpu火焰圖，是用來分析程序沒有有效利用cpu的時候，消耗在什麼地方了，在這裏（http://www.brendangregg.com/FlameGraphs/offcpuflamegraphs.html）有詳細的介紹。數據收集比on-cpu火焰圖要複雜，可使用大名鼎鼎的春哥提供的openresty-systemtap-toolkit（https://github.com/openresty/openresty-systemtap-toolkit）包。春哥的項目頁面中沒有詳細說明的是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

 

安裝時可能還會報錯：

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火焰圖以下：

 

 

我還不能徹底解讀這張圖，可是已經能夠明顯看到，對Registry文件（Filebeat用於記錄文件採集列表和offset數據）的寫操做佔了必定比例。因而，嘗試將Filebeat的spool_size（每完成這麼多條日誌更新一次Registry文件）設置爲10240，默認值的5倍，運行測試cpu已經能夠跑到95%以上。而將Registry設置到/dev/shm/下也一樣能夠解決測試時cpu跑不滿的問題。

 

這就否認了上面對鎖使用不當影響性能的猜想。在實際應用時spool_size的設置應當依據結合了output端（如寫入到Kafka）的測試數據來決定。

 

 

至此，優化結束，達到了最第一版本性能的3倍！
各個版本的具體運行性能數據以下圖所示。

 

 

須要稍做說明的是：

1.Filebeat開發是基於5.3.1版本，go版本是1.8

 

2.Logstash的測試經過-w 1參數配置使用一個

工做進程，並未限制使用一個core

 

3.執行時間包括了程序的啓動時間（Logstash的啓動時間有將近20秒）

 

最終的優化結果是，針對特定格式和長度的日誌解析能力在PC上達到了每秒25000條，即便在CPU主頻較低的生產服務器上，也能夠達到每秒20000條。

 

Go的高性能真不是吹的，固然是要在足夠的優化後：）