大幅提升 golang 寫日誌序列化效能實踐

這是一個建立於 的文章，其中的資訊可能已經有所發展或是發生改變。

    線上服務，需要記錄日誌量比較大，便於排查問題，同時，線上要求所有日誌需要經過rsyslog 灌到kafka 中去，我們日誌需要按規定格式序列化。我們使用的log庫是 "github.com/Sirupsen/logrus"。 那麼問題來了，golang 的序列化效能真的是一言難盡。

    從網上資料來看，Protocol Buffers  效能好於json， 而使用json 的話，有個很經典的效能對比圖，

    

    具體資料不太重要，結論就是 官方的json 最差，滴滴開源的json 庫大致是目前市面最好。然後我們就列出了幾個方案。

    第一個方案，使用monkey patch ，替換到系統的encoding/json。 第二個方案是直接在log 模組中直接重寫json formater 。由於第一種方式會導致調試的時候調用棧錯亂，我們重寫了json formater。 然而，真的如大家認為的一樣，使用jsoniter 效能會有至少一倍以上提升嗎？答案是不一定！

    經過我們pprof 分析，我們替代json庫後的映像如下：

    

從時間上看，序列化花了9.3s，這時間是不能忍受的。然後，出於疑問，我將原始json formater 的調用棧圖也打出來了，如下：

    結果非常神奇，原生的encoding/json 打日誌竟然比滴滴開源的這個庫還要快？然後開源的庫是有問題的？還是我自己有問題？帶著疑惑看了下我們自己實現的json formater 和 官方的benchmark。

    我們的json formater 如下：    

package libsimport ("fmt""github.com/json-iterator/go""github.com/sirupsen/logrus""strings")type fieldKey string// FieldMap allows customization of the key names for default fields.type FieldMap map[fieldKey]string// Fields type, used to pass to `WithFields`.type Fields map[string]interface{}// JSONFormatter formats logs into parsable jsontype JSONFormatter struct {// TimestampFormat sets the format used for marshaling timestamps.TimestampFormat string// DisableTimestamp allows disabling automatic timestamps in outputDisableTimestamp boolFieldMap FieldMapService string}func NewJSONFormatter(service string) *JSONFormatter {format := JSONFormatter{Service: service}return &format}// Format renders a single log entryfunc (f *JSONFormatter) Format(entry *logrus.Entry) ([]byte, error) {data := make(Fields, len(entry.Data)+3)data["service"] = f.Servicedata["msg"] = entry.Messagedata["task_id"] = ""if temp, ok := entry.Data["task_id"]; ok {data["task_id"] = temp.(string)}data["log_date"] = entry.Time.Format("2006-01-02T15:04:05+08:00")var json = jsoniter.ConfigCompatibleWithStandardLibraryserialized, err := json.Marshal(&data)if err != nil {return nil, fmt.Errorf("Failed to marshal fields to JSON, %v", err)}return append(serialized, '\n'), nil}

    這裡的json formater 是沒有問題的和 git 上原生的基本一模一樣。

    然後，我們看了下jsoniter 的官方benchmark ，跑了下，的確是比官方json 效能高一倍以上！問題來了，官方使用的是struct，而logrus 使用的是map，這個是否是關鍵？

    自己實現了個demo，簡單的測試了下：

package mainimport (    "time"    "fmt"    "github.com/json-iterator/go"    "encoding/json")type Data struct {    ceshi string    ceshi1 string    ceshi2 string    ceshi3 string}var datamap map[string]stringfunc main() {    data := Data{        ceshi: "ceshi111111111111111111111111111111111111111",        ceshi1: "ceshi111111111111111111111111111111111111111",        ceshi2: "ceshi111111111111111111111111111111111111111",        ceshi3: "ceshi111111111111111111111111111111111111111",    }    t1 := time.Now()    for i:=0; i<100000; i++{        json.Marshal(&data)    }    cost := time.Since(t1).Nanoseconds()    fmt.Printf("encoding/json, using struct %v\n", cost)    var jsoner = jsoniter.ConfigCompatibleWithStandardLibrary    t2 := time.Now()    for i:=0; i<100000; i++{        jsoner.Marshal(&data)    }    cost = time.Since(t2).Nanoseconds()    fmt.Printf("json-iterator, using struct %v\n", cost)    data1 := map[string]string{}    data1["ceshi"] = "ceshi111111111111111111111111111111111111111"    data1["ceshi1"] = "ceshi111111111111111111111111111111111111111"    data1["cesh2"] = "ceshi111111111111111111111111111111111111111"    data1["ceshi3"] = "ceshi111111111111111111111111111111111111111"    t3 := time.Now()    for i:=0; i<100000; i++{          json.Marshal(&data1)    }    cost = time.Since(t3).Nanoseconds()    fmt.Printf("encoding/json,using map %v\n", cost)    t4 := time.Now()    for i:=0; i<100000; i++{        jsoner.Marshal(&data1)    }    cost = time.Since(t4).Nanoseconds()    fmt.Printf("json-iterator, using map %v\n", cost)}

    輸出結果如下：

encoding/json, using struct 20051594json-iterator, using struct 15108556encoding/json,using map 224949830json-iterator, using map 195824204

    結果是使用struct 序列化，效能比使用map 好一個數量級，不管是使用標準庫還是iterator，在同樣對struct marshl的情況下，json-iterator 效能好於encoding/json。

    由此，關鍵點就非常明確了，當我們事先json formater 的時候，不能照著官方源碼抄，或者直接使用官方的json formater,這都是有極大問題的。想下其實也能理解，我們寫日誌的時候key 是不定的，所以只能使用map。

    下面是我們修改的json formater:

package loggingimport ("fmt""github.com/json-iterator/go""github.com/Sirupsen/logrus")type fieldKey string// FieldMap allows customization of the key names for default fields.type FieldMap map[fieldKey]string// Fields type, used to pass to `WithFields`.type Fields map[string]interface{}// JSONFormatter formats logs into parsable jsontype JSONFormatter struct {// TimestampFormat sets the format used for marshaling timestamps.TimestampFormat string// DisableTimestamp allows disabling automatic timestamps in outputDisableTimestamp boolFieldMap FieldMapService string}func NewJSONFormatter(service string) *JSONFormatter {format := JSONFormatter{Service: service}return &format}//根據需要，將結構體的key 設定成自己需要的type Data struct {Service string`json:"service"`Msgstring`json:"msg"`TaskIdstring`json:"task_id"`LogDatastring`json:"log_date"`}// Format renders a single log entryfunc (f *JSONFormatter) Format(entry *logrus.Entry) ([]byte, error) {data := Data{Service: f.Service,Msg: entry.Message,TaskId: "",}if temp, ok := entry.Data["task_id"]; ok {data.TaskId = temp.(string)}data.LogData = entry.Time.Format("2006-01-02T15:04:05+08:00")var json = jsoniter.ConfigCompatibleWithStandardLibraryserialized, err := json.Marshal(&data)if err != nil {return nil, fmt.Errorf("Failed to marshal fields to JSON, %v", err)}return append(serialized, '\n'), nil}

    通過以上最佳化，序列化時間縮短到不到3s：

    

    總結，golang 需要頻繁寫日誌的時候，要麼使用text format ，要麼json format 的時候，特別主要下序列化的對象。具體，為什麼json-iterator 對map 序列化效能下降的如此厲害，需要從源碼角度分析，下次有空再分析。