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

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

1. 前言

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

2. 实验

首先来看几个实验 完整程序见 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里，这样就会导致日志消息丢失，因此是否要使用异步写入的方式，还请读者权衡使用。另外建议大家还是通过在生产、测试、开发环境设置不同的日志级别，来控制日志的数据量，提高服务的吞吐能力。

后记

2021年5月10日

提高打印日志的速度的一些方法

1）由于golang在操作文件描述符时有锁(写文件时有加锁)，可以将日志打印到不同的日志文件中。 2）观察io.wait，如果io.wait值较大，则可能磁盘IO有瓶颈，可以考虑将日志文件分布到不同的磁盘上。

2021年5月11日
如果使用channel来cache日志，还应当考虑高负载情况下，channel被打满的情况

func (fa *FileWriteAsyncer) Write(data []byte) (int, error) {
	select {
	case fa.ch <- data:
		return len(data), nil
	default:
	    // 直接丢弃多余的日志
		// 注意: 需要在metric中记录丢弃的日志数量
		return 0, errors.New("Log channel is full")
	}
}

2022年9月14日
也可以使用bufio库, 增加缓冲区的大小，减少系统调用syscall.Write

func NewWriterSize(w io.Writer, size int) *Writer