玩转高性能日志库ZAP(5)-异步写日志

版权声明 本站原创文章 由 萌叔 发表
转载请注明 萌叔 | http://vearne.cc

在复杂的业务逻辑中，一个请求就有可能带来10 ~ 30条日志的写入。打日志造成的开销很大，是无法被忽略的一环。怎样才能提高日志的写入速度?

首先来看几个实验
完整程序见 vearne/golab/zaplog
中的log.go log2.go log3.go

2.1 打印到文件

打印到指定文件中，并做归档

package zaplog

import (
    "go.uber.org/zap"
    "go.uber.org/zap/zapcore"
    "gopkg.in/natefinch/lumberjack.v2"
)

func InitLogger() *zap.Logger {
    // 动态调整日志级别
    alevel := zap.NewAtomicLevel()

    hook := lumberjack.Logger{
        Filename:   "/tmp/tt1.log",
        MaxSize:    1024, // megabytes
        MaxBackups: 3,
        MaxAge:     7,    //days
        Compress:   true, // disabled by default
    }
    w := zapcore.AddSync(&hook)

    alevel.SetLevel(zap.InfoLevel)
    encoderConfig := zap.NewProductionEncoderConfig()
    encoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder

    core := zapcore.NewCore(
        zapcore.NewConsoleEncoder(encoderConfig),
        w,
        alevel,
    )

    return zap.New(core)
}

2.2 打印到终端

这应该是官方推荐的方式，特别是对于使用docker容器的场景，应用开发者的配置非常简单，无需指定日志文件路径，由容器管理服务采集容器的标准输出并归档。

package zaplog

import (
    "go.uber.org/zap"
    "log"
)

func InitLogger2() *zap.Logger {
    // 默认是Info级别
    logcfg := zap.NewProductionConfig()
    // 关闭日志采样采样
    logcfg.Sampling = nil
    //logcfg.Encoding = "json"
    logcfg.Encoding = "console"

    logger, err := logcfg.Build()
    if err != nil {
        log.Println("error", err)
    }

    return logger
}

2.3 实验结果

测试环境:

• MacBook: 10.12.6
• 处理器: 2.3GHz Intel Core i5
• 内存 8GB 2133MHz LPDDR3

goarch: amd64
pkg: github.com/vearne/golab/zaplog
BenchmarkZapFile-4        308242          4141 ns/op
BenchmarkZapStdout-4
1.577931741156899e+09   info    zaplog/log_test.go:23   hello world!
... 
  265311          4225 ns/op

写文件和写控制台的性能差不多, 每秒钟差不多30w条。假定一个请求产生30条日志，也就是说即使处理这个请求没有任何逻辑，光是打日志，QPS也就差不多1w左右。(这也是很多服务压测的QPS无法超过1w的原因)。那么能否将日志打印的性能能否再提高一点呢？

2.4 异步写入

追踪代码，萌叔发现对文件的写入逻辑在此函数中

// Write implements io.Writer.
func (fd *FD) Write(p []byte) (int, error) {
    // 注意: 对文件描述符有读写锁控制
    if err := fd.writeLock(); err != nil {
        return 0, err
    }
    defer fd.writeUnlock()
    if err := fd.pd.prepareWrite(fd.isFile); err != nil {
        return 0, err
    }
    var nn int
    for {
        max := len(p)
        if fd.IsStream && max - nn > maxRW {
            max = nn + maxRW
        }
        // 执行"系统调用"将将数据从用户空间写入(拷贝)到内核缓冲区
        // 数据最终落盘，由内核负责
        n, err := syscall.Write(fd.Sysfd, p[nn:max])
        if n > 0 {
            nn += n
        }
        if nn == len(p) {
            return nn, err
        }
        if err == syscall.EAGAIN && fd.pd.pollable() {
            if err = fd.pd.waitWrite(fd.isFile); err == nil {
                continue
            }
        }
        if err != nil {
            return nn, err
        }
        if n == 0 {
            return nn, io.ErrUnexpectedEOF
        }
    }
}

每次打印日志，都会执行syscall.Write，频繁执行系统调用开销很大，完全可以改为批量执行。因此这里把对文件的写入改为批量、异步逻辑。

package zaplog

import (
    "bytes"
    "github.com/natefinch/lumberjack"
    "go.uber.org/zap"
    "go.uber.org/zap/zapcore"
    "time"
)

// 实现WriteSyncer接口
/*
type WriteSyncer interface {
    io.Writer
    Sync() error
}
*/
type FileWriteAsyncer struct {
    innerLogger *lumberjack.Logger
    ch          chan []byte
    syncChan    chan struct{}
}

func NewFileWriteAsyncer(filepath string) *FileWriteAsyncer {
    fa := &FileWriteAsyncer{}
    fa.innerLogger = &lumberjack.Logger{
        Filename:   filepath,
        MaxSize:    1024, // megabytes
        MaxBackups: 3,
        MaxAge:     7,    //days
        Compress:   true, // disabled by default
    }
    fa.ch = make(chan []byte, 10000)
    fa.syncChan = make(chan struct{})
    // 批量异步写入到文件中
    go batchWriteLog(fa)
    return fa

}

func (fa *FileWriteAsyncer) Write(data []byte) (int, error) {
    fa.ch <- data
    return len(data), nil
}

func (fa *FileWriteAsyncer) Sync() error {
    fa.syncChan <- struct{}{}
    return nil
}

func batchWriteLog(fa *FileWriteAsyncer) {
    buffer := bytes.NewBuffer(make([]byte, 0, 10240))

    ticker := time.NewTicker(time.Millisecond * 200)
    //var record []byte
    var err error
    for {
        select {
        case <-ticker.C:
            if len(buffer.Bytes()) > 0 {
                _, err = fa.innerLogger.Write(buffer.Bytes())
                if err != nil {
                    panic(err)
                }
                buffer.Reset()
            }

        case record := <-fa.ch:
            buffer.Write(record)
            if len(buffer.Bytes()) >= 1024*4 {
                _, err = fa.innerLogger.Write(buffer.Bytes())
                if err != nil {
                    panic(err)
                }
                buffer.Reset()
            }
        case <-fa.syncChan:
            if len(buffer.Bytes()) > 0 {
                _, err = fa.innerLogger.Write(buffer.Bytes())
                if err != nil {
                    panic(err)
                }
                buffer.Reset()
            }
            break
        }
    }

}

func InitLogger3() *zap.Logger {
    alevel := zap.NewAtomicLevel()
    alevel.SetLevel(zap.InfoLevel)
    encoderConfig := zap.NewProductionEncoderConfig()
    encoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder

    core := zapcore.NewCore(
        zapcore.NewConsoleEncoder(encoderConfig),
        NewFileWriteAsyncer("/tmp/tt3.log"),
        alevel,
    )

    return zap.New(core)
}

实验结果:

goarch: amd64
pkg: github.com/vearne/golab/zaplog
BenchmarkZapFile-4        260256          4377 ns/op         112 B/op          4 allocs/op
BenchmarkZapStdout-4
1.577936240870677e+09   info    zaplog/log_test.go:23   hello world!
...
  248214          4372 ns/op         336 B/op          7 allocs/op
BenchmarkAsync-4          722610          1666 ns/op         112 B/op          4 allocs/op

日志写入逻辑改为批量异步写入之后，性能提升了一倍多。日志同步变异步虽然能提高日志的写入速度，但是它带来一个风险点。比如程序突然崩溃，然而日志数据还在channel里，这样就会导致日志消息丢失，因此是否要使用异步写入的方式，还请读者权衡使用。另外建议大家还是通过在生产、测试、开发环境设置不同的日志级别，来控制日志的数据量，提高服务的吞吐能力。

请我喝瓶饮料