記一次獲得3倍效能的go程式最佳化實踐，及on-cpu/off-cpu火

先把結論列在前面：

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包。Linux下有一個C實現的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包後，對我們包含了日誌格式結構體定義的程式檔案執行easyjson命令，會生成一個xxx_easyjson.go的檔案，裡面包含了這個結構體專用的Marshal/Unmarshal方法。這樣一來，處理時間又縮短為61秒，效能提高15%。

這時，程式碼在我面前，已經想不出有什麼大的方面還可以最佳化的了。是時候該本文的另一個主角，火焰圖出場了。

---

火焰圖是效能分析的一個有效工具，是它的說明。通常看到的火焰圖，是指on-cpu火焰圖，用來分析cpu都消耗在哪些函式呼叫上。

安裝完工具後，先對目前版本的程式執行一次效能測試，按照說明抓取資料生成火焰圖如下。

對於c/go程式是通用的。對於go程式，也可以使用自帶的net/http/pprof包作為資料來源，然後安裝uber的工具來自動呼叫FlameGraph指令碼生成on-cpu火焰圖，執行會稍為簡便一些。參見go-torch說明。

perf_on_cpu_orig.png

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

從上圖可以看到cpu時間佔用最多的主要有兩塊。一塊是Output處理部分，稍為大頭的是json處理，這塊已經最佳化過沒什麼可以做的了。另一塊就比較奇怪了，是common.MapStr.Clone()方法，居然佔了40%的cpu時間。再往上看，主要是Errorf的處理。一看程式碼，馬上明白了。

func (m MapStr) Clone() MapStr {
    result := MapStr{}    for k, v := range m {
        innerMap, err := toMapStr(v)        if err == nil {
            result[k] = innerMap.Clone()
        } else {
            result[k] = v
        }
    }    return result
}

common.MapStr是在pipeline中存放日誌內容的結構體，它的Clone()方法實現裡判斷一個子鍵值是否為巢狀的Mapstr結構時，是透過判斷toMapStr()方法是否返回error。從這裡看，生成error物件的代價是非常可觀的。於是，一個顯然的fix，就是將toMapStr()中的判斷方法移到Clone()中並避免生成error。

Version 5

對修改後的程式碼重新生成一張火焰圖如下。

perf_on_cpu_opt.png

這時common.MapStr.Clone()從圖中已經幾乎找不見了，證明花費的cpu時間已經可以忽略不計。
測試時間一下子縮短到了46秒，節省了33%，非常大的改善！

---

到現在，還有一個之前未提到的問題沒有解決——在限制使用一個core之後，測試執行時cpu利用率只能跑到82%左右。是不是由於有鎖存在影響了效能呢？

這時候，又該請off-cpu火焰圖出場了。Off-cpu火焰圖，是用來分析程式沒有有效利用cpu的時候，消耗在什麼地方了，在有詳細的介紹。資料收集比on-cpu火焰圖要複雜，可以使用大名鼎鼎的春哥提供的包。春哥的專案頁面中沒有詳細說明的是kernel-devel和debuginfo包的安裝方法。在此也記錄一下。

# kernel-devel沒有問題，直接yum安裝sudo yum install -y kernel-devel# debuginfo，在CentOS7中需要這樣裝sudo vim /etc/yum.repos.d/CentOS-Debuginfo.repo
修改為enable=1sudo 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
需要從下載key寫入到/etc/pki/rpm-gpg/RPM-GPG-KEY-CentOS-Debug-7

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

perf_off_cpu_orig.png

我還不能完全解讀這張圖，但是已經可以明顯看到，對Registry檔案（Filebeat用於記錄檔案採集列表和offset資料）的寫操作佔了一定比例。於是，嘗試將Filebeat的spool_size（每完成這麼多條日誌更新一次Registry檔案）設定為10240，預設值的5倍，執行測試cpu已經可以跑到95%以上。而將Registry設定到/dev/shm/下也同樣可以解決測試時cpu跑不滿的問題。

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

---

至此，最佳化結束，達到了最初版本效能的3倍！
各個版本的具體執行效能資料如下圖所示。

performance_compare.png

需要稍作說明的是：

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

2. Logstash的測試透過-w 1引數配置使用一個工作程式，並未限制使用一個core

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

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

Go的高效能真不是吹的，當然是要在足夠的最佳化後：）

附錄，關於go的效能有一篇這樣的討論，有興趣可以看看：

作者：petergz
連結：