Significantly improved Golang write log serialization performance practices

This is a creation in Article, where the information may have evolved or changed.

Online services, need to record a large amount of log, easy to troubleshoot problems, at the same time, the line requires that all logs need to be rsyslog into the Kafka, our log needs to be serialized in accordance with the specified format. The log library We use is "Github.com/sirupsen/logrus". So the problem is, Golang's serialization performance is really long story.

Judging from the online data, Protocol buffers performance is better than JSON, and using JSON, there is a very classic performance comparison chart,

The details are less important, and the result is that the official JSON is the worst, and the drop-open JSON library is generally the best in the market. Then we listed a few options.

The first scenario, using Monkey patch, is replaced with the Encoding/json of the system. The second option is to directly rewrite the JSON formater directly in the log module. Because the first way would cause the call stack to be garbled when debugging, we rewrote the JSON formater. However, is it true that, as you might think, there will be at least one more boost to using Jsoniter performance? The answer is not necessarily!

After our pprof analysis, we replace the JSON library with the following image:

In terms of time, serialization took 9.3s, which was intolerable at this time. Then, out of doubt, I have the call stack diagram of the original JSON Formater, as follows:

The result is very magical, the original Encoding/json to hit the log unexpectedly than the drip open source of this library is faster? Then the open source Library is problematic? Or am I having a problem with myself? With a puzzled look at our own implementation of the JSON Formater and the official benchmark.

Our JSON formater is as follows:

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: 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}

The JSON formater here is no problem and basically identical to the original on Git.

Then we looked at the official benchmark of the next Jsoniter, and ran down, indeed more than the official JSON performance more than one times! The problem is, the official use of the struct, and Logrus using a map, is this the key?

I realized a demo, a simple test of the following:

Package Mainimport ("Time" "FMT" "Github.com/json-iterator/go" "Encoding/json") type Data struct {Ceshi St        Ring 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"] = "ceshi111111111111111 111111111111111111111111 "data1[" ceshi1 "] =" ceshi111111111111111111111111111111111111111 "data1[" cesh2 "] =" ceshi1111111 11111111111111111111111111111111 "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)}

The output results are as follows:

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

The result is the use of struct serialization, which performs better than Encoding/json in the case of the same marshl to the struct, whether it is using the standard library or the iterator, using the order of magnitude of the map good one.

As a result, the key point is very clear, when we first JSON formater, can not be copied according to the official source code, or directly use the official JSON formater, this is a great problem. Think of actually can understand, we write the log when key is uncertain, so can only use map.

Here is the JSON formater we modified:

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: 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}//set the struct key to the type Data struct {service string ' JSON: "Service" ' msgstring ' JSON: "MSG", as needed 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}

With the above optimizations, the serialization time is reduced to less than 3s:

In summary, Golang requires frequent log writing, either using text format or JSON format, especially when serializing objects. Specifically, why Json-iterator to map serialization performance is so severe, need to analyze from the source angle, the next time to analyze the space.