Design and implementation of zap, a high-performance Go logging library

Recently I’ve been learning how to make code run more efficiently in development, and while browsing through various good logging designs, I came across a logging library called zap from uber that caught my attention, with its main feature of extreme performance and memory allocation optimizations.

For me, I was originally using logrus as log output in my project, but when I saw the benchmark of zap, I felt that it beat logrus in terms of performance, so that’s what drove me to see how it was optimized.

Of course, besides that, I wanted to get more familiar with it so that I could use the library more efficiently and avoid being unable to locate it when problems arise.

Here is the benchmark to give you some motivation to read on.

zap design

Instantiation of log

To get started, we can use the official example to understand the internal components of zap.

1

log := zap.NewExample()

The NewExample function shows a Core structure to be created by NewCore, which we should be able to guess is the core of zap based on its name.

For a logging library, there are three main categories.

1. how the input data needs to be serialized.
2. where to store the input data after serialization, be it console or file, or somewhere else.
3. and then the level of logging, whether it is Debug, Info or Error.

Similarly with zap, the three parameters that need to be passed when creating a Core structure with NewCore are: Encoder for the input data, WriteSyncer for the log data, and LevelEnabler for the log level.

In addition to the NewExample constructor, zap also provides NewProduction and NewDevelopment to construct log instances.

1
2

log, _  = zap.NewProduction()
log, _  = zap.NewDevelopment()

These two functions create the parameters needed for NewCore by constructing a Config structure and then calling the Build method, which then instantiates the log instance.

Output of log data

After initializing the log instance, you can print the log using Info, Debug, Error, etc.

1
2
3
4
5
6
7

    log  = zap.NewExample()
    url := "http://example.org/api"
    log.Info("failed to fetch URL",
        zap.String("url", url),
        zap.Int("attempt", 3),
        zap.Duration("backoff", time.Hour),
    )

Let’s take a look at the steps for zap to print a structured log:

1. first check the logging configuration level, for example, the Error logging configuration level must not output the Debug log.
2. then the log data is encapsulated into an Entry instance.
3. add multiple Cores to the CheckedEntry instance because multiCore can be passed in the zap.
4. iterate through the Cores in the CheckedEntry instance.
   1. serialize the log data into the Buffer according to the Encoder in the Core;
   2. the WriteSyncer then outputs the log data from the Buffer.

Interface and framework design

The code structure is designed with a simple interface encapsulation to achieve a variety of styles of configuration combinations to meet various needs. The top-level design implements three logs used to achieve different functions.

Logger : more cumbersome to use, only structured output can be used, but better performance.

SugaredLogger: can use Printf to output logs, performance is about 40% worse than Logger; zapgrpc: can use Printf to output logs, performance is about 40% worse than Logger.

zapgrpc: used for grpc logging output.

Logger can be easily converted to SugaredLogger and zapgrpc by design; these Loggers require passing in a Core interface implementation class to create.

Core interface: zap also provides a variety of implementation options: NewNopCore, ioCore, multiCore, hook.

The most commonly used are ioCore, multiCore, from the name you can see that multiCore is a configuration that can contain multiple ioCore, for example, you can make the Error log output one log format and set a log output destination, so that the Info log output in another log format to another place.

As mentioned above, the Core implementation class ioCore requires three objects to be passed in: Encoder, the encoder of the input data, WriteSyncer, the destination of the log data, and LevelEnabler, the log level.

Encoder interface: zap provides implementations of consoleEncoder, jsonEncoder, which provide log output in console format and JSON format respectively, and these Encoders have their own serialization implementations, which allows for faster formatting of code.

EncoderConfig : The Encoder described above also allows the user to flexibly configure the log output format according to the EncoderConfig configuration, from the key name of the log message, the log level name, to the definition of the time format output, the definition of the method name can be flexibly configured through it.

WriteSyncer interface : zap provides a single log output implementation of writerWrapper and a multiWriteSyncer implementation that can output logs to multiple locations.

Entry : With the configuration out of the way, it’s time to encapsulate the log data. First, the log data will be encapsulated into an Entry, which contains the log name, log time, log level, and log data information, no Field information, and then experience Core’s Check method to generate a CheckedEntry instance after the log level is verified.

CheckedEntry contains all the information about the log data, including the above-mentioned Entry, call stack information, etc.

Performance

Using Object Pools

zap reuses a large number of objects that can be reused through the object pools provided by sync.

zap When instantiating CheckedEntry, Buffer, Encoder and other objects, it will get them directly from the object pool, instead of instantiating a new one directly, so that reusing objects can reduce the pressure of GC and reduce memory allocation.

Avoid reflection

If we use the official log library, output the log like this.

1

log.Printf("%s login, age:%d", "luoluo", 19)

The Printf function called by log actually calls the fmt.Sprintf function to format the log data for output.

1
2
3

func Printf(format string, v ...interface{}) {
    std.Output(2, fmt.Sprintf(format, v...))
}

However, the efficiency of fmt.Sprintf is actually very low, and by looking at the source code of fmt.

1. the type accepted by fmt.Sprintf is interface{}, which uses reflection internally.
2. fmt.Sprintf is used for formatting strings, which requires parsing format strings such as %s, %d and so on, increasing the time spent on parsing.

However, in zap, the built-in Encoder is used, which stitches log data in byte form through the internal Buffer, reducing the performance loss caused by reflection; and zap uses structured logs, so there are no %s or %d identifiers to parse, which is also a performance improvement.

A more efficient and flexible serializer

Both serializers can be configured flexibly according to the EncoderConfig passed in. This flexible configuration is not just the name of the log output key, but the user-defined Encoder implementation can be called by passing in a function in EncoderConfig.

The standard library serialization tool is used for serializing JSON like logrus, which is also less efficient.

zap code analysis

Since I feel that the zap code is still written in an elegant way, here is a little bit of source code analysis.

Initialization

Initializing Core

As we learned in the diagram above, Core has 4 implementation classes, so let’s take the most commonly used ioCore as an example to explain.

1
2
3
4
5

type ioCore struct {
    LevelEnabler
    enc Encoder
    out WriteSyncer
}

The ioCore is very simple and requires a total of three fields: Encoder for the input data, WriteSyncer for the log data destination, and LevelEnabler for the log level.

1
2
3
4
5
6
7

func NewCore(enc Encoder, ws WriteSyncer, enab LevelEnabler) Core {
    return &ioCore{
        LevelEnabler: enab,
        enc:          enc,
        out:          ws,
    }
}

The NewCore function also returns an object pointer when used to create an ioCore.

Initializing a Logger

zap will instantiate a Logger with the New function.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12

func New(core zapcore.Core, options ...Option) *Logger {
    if core == nil {
        return NewNop()
    }
    log := &Logger{
        core:        core,
        errorOutput: zapcore.Lock(os.Stderr),
        addStack:    zapcore.FatalLevel + 1,
        clock:       _systemClock,
    }
    return log.WithOptions(options...)
}

The New function sets up the appropriate default fields, including the core instance, the error log output location, the output level of the stack log, the log time, etc., and then instantiates a Logger object to return a pointer.

The information of the Logger structure is as follows.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18

type Logger struct {
    core zapcore.Core
    // 是否是开发模式
    development bool
    // 是否打印行号
    addCaller   bool
    onFatal     zapcore.CheckWriteAction // default is WriteThenFatal

    name        string
    // 错误日志输出
    errorOutput zapcore.WriteSyncer
    // 输出调用堆栈
    addStack zapcore.LevelEnabler
    // 打印调用者的行号
    callerSkip int

    clock Clock
}

The Logger structure will contain a lot of configuration information, and we can add the corresponding parameters through WithOptions in our development. For example, add the log line number.

1

log := zap.New(core).WithOptions(zap.AddCaller())

The AddCaller function creates a callback hook for WithOptions to execute, which is the beauty of functional programming.

1
2
3
4
5
6
7
8

func (log *Logger) WithOptions(opts ...Option) *Logger {
    c := log.clone()
    for _, opt := range opts {
    // 调用 Option 接口的方法 
        opt.apply(c)
    }
    return c
}

WithOptions you can pass in an array of Options, then iterate through the array and call the apply method.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21

type optionFunc func(*Logger)

func (f optionFunc) apply(log *Logger) {
    f(log)
}
// 定义 Option 接口
type Option interface {
    apply(*Logger)
}

func AddCaller() Option {
  // 返回 Option
    return WithCaller(true)
}

func WithCaller(enabled bool) Option {
  // 将 func 强转成 optionFunc 类型
    return optionFunc(func(log *Logger) {
        log.addCaller = enabled
    })
}

The code here is very interesting. In go, a function is also a type, and like a struct, it can have a method.

Here optionFunc is a function type that implements the apply method, so it is equivalent to inheriting the Option interface. Then in the WithCaller, optionFunc is used to wrap a function in a layer, which looks fantastic, but is actually no different from int64(123).

Then in the WithOptions function, the function returned by the WithCaller is converted to optionFunc and passed to log for execution, which is equivalent to changing the addCaller property of log.

If you don’t understand it, you can try it yourself on the compiler.

Printing the log

The entire process of printing the log is as follows.

1. first, get the CheckedEntry instance and encapsulate the corresponding log data;
2. then encode it according to the encoder encapsulated in the core, and put the encoded content into a buffer.
3. output the contents of the buffer to the WriteSyncer encapsulated in the core.

After we initialize the Logger, we can use it to call the appropriate Info, Warn, Error, etc. methods to print the log output. Since the output methods are the same for all log levels, here we will analyze them through the Info method.

1
2
3
4
5
6
7

func (log *Logger) Info(msg string, fields ...Field) {
    // 检查该日志是否应该被打印
    if ce := log.check(InfoLevel, msg); ce != nil {
        // 打印日志
        ce.Write(fields...)
    }
}

This method first calls the check method to check whether the current log data should be printed at the configured log level.

For Info log level, InfoLevel is passed in, and for Error log level, ErrorLevel is passed in. zap log levels are defined by these constants.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14

type Level int8

const ( 
    DebugLevel Level = iota - 1 
    InfoLevel 
    WarnLevel 
    ErrorLevel 
    DPanicLevel 
    PanicLevel 
    FatalLevel

    _minLevel = DebugLevel
    _maxLevel = FatalLevel
)

The minimum DebugLevel starts at -1.

check

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46

func (log *Logger) check(lvl zapcore.Level, msg string) *zapcore.CheckedEntry { 
    const callerSkipOffset = 2
    // 判断传入的日志等级是否应该打印
    if lvl < zapcore.DPanicLevel && !log.core.Enabled(lvl) {
        return nil
    }

    // 将日志数据封装成一个 Entry
    ent := zapcore.Entry{
        LoggerName: log.name,
        Time:       log.clock.Now(),
        Level:      lvl,
        Message:    msg,
    }
    //如果能写日志则返回一个 CheckedEntry 实例指针
    ce := log.core.Check(ent, nil)
    willWrite := ce != nil 
    ... 
    if !willWrite {
        return ce
    }

    ce.ErrorOutput = log.errorOutput
    // 判断是否打印调用行号
    if log.addCaller {
        // 获取调用者的栈帧
        frame, defined := getCallerFrame(log.callerSkip + callerSkipOffset)
        if !defined {
            fmt.Fprintf(log.errorOutput, "%v Logger.check error: failed to get caller\n", ent.Time.UTC())
            log.errorOutput.Sync()
        }
        // 设值调用者 entry
        ce.Entry.Caller = zapcore.EntryCaller{
            Defined:  defined,
            PC:       frame.PC,
            File:     frame.File,
            Line:     frame.Line,
            Function: frame.Function,
        }
    }
    if log.addStack.Enabled(ce.Entry.Level) {
        // 封装调用栈信息
        ce.Entry.Stack = StackSkip("", log.callerSkip+callerSkipOffset).String
    } 
    return ce
}

The Enabled method of the core is called first to determine if the log should be printed. Since the log level is actually an int8 type, this is a straightforward determination based on size.

1
2
3

func (l Level) Enabled(lvl Level) bool {
    return lvl >= l
}

After determining that there are no problems, the Check method is called to get the CheckedEntry instance pointer. After getting the CheckedEntry instance pointer, it will set the value according to the configuration information and then return.

Here is how to get the CheckedEntry instance pointer.

1
2
3
4
5
6
7
8

func (c *ioCore) Check(ent Entry, ce *CheckedEntry) *CheckedEntry {
    // 检查该 level 日志是否应该被打印
    if c.Enabled(ent.Level) {
        // 获取 CheckedEntry
        return ce.AddCore(ent, c)
    }
    return ce
}

The main thing is that the ce passed in is a nil pointer, but that doesn’t mean that Go calls its AddCore method (which would be an error on java).

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27

var (
    _cePool = sync.Pool{New: func() interface{} {
        // Pre-allocate some space for cores.
        return &CheckedEntry{
            cores: make([]Core, 4),
        }
    }}
)

func (ce *CheckedEntry) AddCore(ent Entry, core Core) *CheckedEntry {
    if ce == nil {
        // 从 _cePool 里面获取 CheckedEntry 实例
        ce = getCheckedEntry()
        ce.Entry = ent
    }
    // 因为可能为 multi core 所以这里需要 append 一下
    ce.cores = append(ce.cores, core)
    return ce
}

func getCheckedEntry() *CheckedEntry {
    // 从 pool 中获取对象
    ce := _cePool.Get().(*CheckedEntry)
    // 重置对象的属性
    ce.reset()
    return ce
}

The AddCore method is also very simple, you should take a look at it and understand, not much to say.

Write log printing

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15

func (ce *CheckedEntry) Write(fields ...Field) {
    if ce == nil {
        return
    }
    ... 
    var err error
    // 遍历所有 core 写入日志数据
    for i := range ce.cores {
        err = multierr.Append(err, ce.cores[i].Write(ce.Entry, fields))
    }
    ...
    // 将 CheckedEntry 放回到缓存池中
    putCheckedEntry(ce)
    ...
}

This is where we call the Write method of core to write log data, and continue on.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18

func (c *ioCore) Write(ent Entry, fields []Field) error {
    // 调用 Encoder 的 EncodeEntry 方法将日志数据编码
    buf, err := c.enc.EncodeEntry(ent, fields)
    if err != nil {
        return err
    }
    // 将日志数据通过 WriteSyncer 写入
    _, err = c.out.Write(buf.Bytes())
    // 将buffer放回到缓存池中
    buf.Free()
    if err != nil {
        return err
    }
    if ent.Level > ErrorLevel {
        c.Sync()
    }
    return nil
}

The Write method calls the EncodeEntry method of the encoder, depending on the encoder. Both the jsonEncoder and the consoleEncoder get a Buffer instance from the bufferpool in the EncodeEntry method and then encapsulate the data in the Buffer instance in a certain format.

Once the data is obtained, the WriteSyncer’s Write method is called to write the log data.

Finally, the Buffer instance is released back into the bufferpool.

Summary

This article explains the design principles and code implementation of zap. We can see that the coding structure is designed in such a way that it can be configured in a simple way to achieve rich functionality. In terms of performance, it reduces the overhead of memory allocation through the use of object pools, reduces the overhead of serialization through a built-in high-performance serializer, and reduces the overhead of formatting log data through a structured log format called fmt.Sprintf.