大幅提升 golang 写日志序列化性能实践

    线上服务，需要记录日志量比较大，便于排查问题，同时，线上要求所有日志需要经过rsyslog 灌到kafka 中去，我们日志需要按规定格式序列化。我们使用的log库是 "github.com/Sirupsen/logrus"。 那么问题来了，golang 的序列化性能真的是一言难尽。

该文章后续仍在不断的更新修改中， 请移步到原文地址http://dmwan.cc

    从网上资料来看，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 libs

import (
	"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 json
type JSONFormatter struct {
	// TimestampFormat sets the format used for marshaling timestamps.
	TimestampFormat string

	// DisableTimestamp allows disabling automatic timestamps in output
	DisableTimestamp bool

	FieldMap FieldMap

	Service string
}

func NewJSONFormatter(service string) *JSONFormatter {
	format := JSONFormatter{Service: service}
	return &format
}

// Format renders a single log entry
func (f *JSONFormatter) Format(entry *logrus.Entry) ([]byte, error) {
	data := make(Fields, len(entry.Data)+3)
	data["service"] = f.Service
	data["msg"] = entry.Message
	data["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.ConfigCompatibleWithStandardLibrary
	serialized, 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 main
import (
    "time"
    "fmt"
    "github.com/json-iterator/go"
    "encoding/json"
)

type Data struct {
    ceshi string
    ceshi1 string
    ceshi2 string
    ceshi3 string
}

var datamap map[string]string

func 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 20051594
json-iterator, using struct 15108556
encoding/json,using map 224949830
json-iterator, using map 195824204

    结果是使用struct 序列化，性能比使用map 好一个数量级，不管是使用标准库还是iterator，在同样对struct marshl的情况下，json-iterator 性能好于encoding/json。

    由此，关键点就非常明确了，当我们事先json formater 的时候，不能照着官方源码抄，或者直接使用官方的json formater,这都是有极大问题的。想下其实也能理解，我们写日志的时候key 是不定的，所以只能使用map。

    下面是我们修改的json formater:

package logging

import (
	"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 json
type JSONFormatter struct {
	// TimestampFormat sets the format used for marshaling timestamps.
	TimestampFormat string

	// DisableTimestamp allows disabling automatic timestamps in output
	DisableTimestamp bool

	FieldMap FieldMap

	Service string
}

func NewJSONFormatter(service string) *JSONFormatter {
	format := JSONFormatter{Service: service}
	return &format
}

//根据需要，将结构体的key 设置成自己需要的
type Data struct {
	Service string	`json:"service"`
	Msg		string	`json:"msg"`
	TaskId	string	`json:"task_id"`
	LogData	string	`json:"log_date"`
}

// Format renders a single log entry
func (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.ConfigCompatibleWithStandardLibrary
	serialized, 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 序列化性能下降的如此厉害，需要从源码角度分析，下次有空再分析。