我是 LEE，老李，一个在 IT 行业摸爬滚打 17 年的技术老兵。
事件背景
过年在家正好闲得没有太多事情，想起年前一个研发项目负责人反馈的问题：“老李啊，我们组一直在使用你这边的 gin 封装的 webservice 框架开发，我们需要一套标准的异步日志输出?？椤Ｏ衷谧槟诤推渌褂?gin 的小伙伴实现的‘各有千秋’不统一，没有一个组或者部门对这部分的代码负责和长期维护。你能不能想想办法?！?/p>
这一看就是掉头发的事情，虽然 gin 封装的 webservice 框架是我开发底层服务包，已经推广到公司所有 golang 开发组使用，现在需要一个统一异步日志输出的?？槭欠裾娴挠幸庖?，要认真的考虑和研究下，毕竟有核心业务团队有这样的需求。
索性打开了 uber-go/zap 日志框架的源代码，看看到底是什么原因推动大家都要手写异步日志?？?。不看不知道，一看吓一跳，项目中 issue#998 就有讨论，我看了下 issue 留言，觉得大家的说法都挺正确，而项目作者一直无动无衷，而且坚信 bufio + 定时 flush 的方式 才是正道，怪不得大家都要自己手写一个异步日志输出?？椤?/p>
心智负担
在要写 uber-go/zap 异步日志?？橹?，首先要明白异步日志?？榈挠诺?、缺点以及适用的场景，这样代码才写的有意义，是真正的解决问题和能帮助到小伙伴的。
关于同步和异步模型的差异，这边就不展开了，估计再写几千字也不一定能说清楚，有需要深入了解的小伙伴，可以自行 baidu，那里有很多相关的文章，而且讲解得非常清晰。这里我就不需要过多解析，而我需要讲的是同步和异步日志?？椤?/p>
- 同步日志：日志信息投递后，必须要等到日志信息写到对应的 io.Writer 中（os.Stdout, 文件等等）并返回，这个调用过程结束。适合 Warning 级别以上日志输出，强记录或者落盘需求的日志信息，不能丢失。
- 异步日志：日志信息投递后，调用过程结束。而日志信息是否能够正确写到对应的 io.Writer 中（os.Stdout, 文件等等）是由异步日志?？楸Ｖ?，不等待调用过程。适合 Warning 级别以下日志输出，尽量存储日志，如果没有存储，丢失也没有关系。
那么我就用一句话说明白这两种日志模型的差别。
- 同步日志：慢，安全，日志不丢
- 异步日志：快，不安全，日志尽力记录
既然这里说到是心智负担，但是真正负担在哪里？ 实际上面已经提到了心智负担的核心内容：就是如何正确的选择一个日志模型。
而我们这边需求是明确知道有部分日志可以丢失，追求接口响应速度，希望有统一的实现，有人维护代码和与整个 gin 封装的 webservice 框架融合的品质。
前置知识
明确了开发的需求，开发的目标。确认了开发有意义，确实能解决问题。那么：就是干!!!
在动之前还是要准备些知识，还要做好结构设计，这样才能解答：一套合理的异步输出模型应该是什么样的？
分享下我理解的一个异步日志模型是什么样的（欢迎大家来“锤”，但是锤我的时候，麻烦轻点哈）
有的小伙伴看到这个图觉得有点眼熟？Kafka？不对，不对，不对，还少了一个 Broker。因为这里不需要对 Producer 实现一个独立的缓冲器和分类器，那么 Broker 这样的角色就不存在了。
简单的介绍下成员角色：
- MessageProducer: 消息和数据生成者
- CriticalSurface: 并发临界面，所有 MessageProducer 都到这边竞争控制权，往 RingBuffer 中写入数据
- RingBuffer: 消息和数据的缓冲（记得缓冲和缓存区别，这边用缓冲就是为了解决 Producer 和 Consumer 和速度差）
- MessageConsumer: 消息和数据消费者
为什么选择上面的模型：
- 希望在现有的 uber-go/zap 的结构上扩展，实现一部分能力，满足功能扩展。
- 不希望重复做轮子，因为轮子做出来，需要有严格的代码测试和压力测试，才能交付生产系统。
- 模型简单，好理解，也好实现。
- 性能比较高，而且架构整体比较合理。
为了实现这个模型，还需要思考如下几个问题：
- CriticalSurface 如何实现？因为要满足多个 MessageBroker 并发使用，那么这个临界面就必须要做，要不然就出现争抢资源失控的情况。
- 为什么要选择 RingBuffer？RingBuffer 是目前速度和效率最好的一种缓冲模型，Linux/Unix 系统中广泛使用。
- 选择 RingBuffer 需要注意些什么？RingBuffer 有快慢指针的问题，如果控制不好，快指针就回覆写慢指针的数据，地址数据丢失的情况。
- MessageConsumer 数量如何限制？如何平衡信息的创建与消费之间的速度差异。
- 如何支持多种日志方式输出类型。(golang 多种 io.Writer 模型)
如果看到这里，估计已经劝退了很多的小伙伴，我想这就是为什么那个研发项目负责人带着团队问题来找我，希望能够得到解决的原因吧。确实不容易。
解决思路
uber-go/zap 代码分析
在认真看看完了 uber-go/zap 的代码以后，发现 uber 就是 uber，代码质量还是非常不错的，很多模块抽象的非常不错。通过一段时间的思考后，确认我们要实现一个独立的 WriteSyncer, 跟 uber-go/zap 中的 BufferedWriteSyncer 扮演相同的角色。
既然要实现，我们先看看 uber-go/zap 中的源代码怎么定义 WriteSyncer 的。
go.uber.org/zap@v1.24.0/zapcore/write_syncer.go
// A WriteSyncer is an io.Writer that can also flush any buffered data. Note
// that *os.File (and thus, os.Stderr and os.Stdout) implement WriteSyncer.
type WriteSyncer interface {
io.Writer
Sync() error
}
WriteSyncer 是一个 interface，也就是我们只要引用 io.Writer 和实现 Sync() error 这样的一个方法就可以对接 uber-go/zap 系统中。那么 Sync() 这个函数到底是干嘛的？ 顾名思义就是让 zap 触发数据同步动作时需要执行的一个方法。但是我们是异步日志，明显 uber-go/zap 处理完日志相关的数据，丢给我实现的 WriteSyncer 以后，就不应该在干预异步日志模块的后期动作了，所以 Sync() 给他一个空壳函数就行了。
当然 uber-go/zap 早考虑到这样的情况，就给一个非常棒的包装函数 AddSync()。
go.uber.org/zap@v1.24.0/zapcore/write_syncer.go
// AddSync converts an io.Writer to a WriteSyncer. It attempts to be
// intelligent: if the concrete type of the io.Writer implements WriteSyncer,
// we'll use the existing Sync method. If it doesn't, we'll add a no-op Sync.
func AddSync(w io.Writer) WriteSyncer {
switch w := w.(type) {
case WriteSyncer:
return w
default:
return writerWrapper{w}
}
}
type writerWrapper struct {
io.Writer
}
func (w writerWrapper) Sync() error {
return nil
}
uber-go/zap 已经把我们希望要做的事情都给做好了，我们只要实现一个标准的 io.Writer 就行了，那继续看 io.Writer 的定义方式。
go/src/io/io.go
// Writer is the interface that wraps the basic Write method.
//
// Write writes len(p) bytes from p to the underlying data stream.
// It returns the number of bytes written from p (0 <= n <= len(p))
// and any error encountered that caused the write to stop early.
// Write must return a non-nil error if it returns n < len(p).
// Write must not modify the slice data, even temporarily.
//
// Implementations must not retain p.
type Writer interface {
Write(p []byte) (n int, err error)
}
哇，好简单。要实现 io.Writer 仅仅只要实现一个 Write(p []byte) (n int, err error) 方法就行了，So Easy !!!!
上手开发
还是回到上一章中的 5 个核心问题，我想到这里应该有答案了：
- MessageProducer：用一个函数实现，实际上就是 Write(p []byte)，接收 uber-go/zap 投递来的消息内容。
- CriticalSurface 和 RingBuffer： 是最核心的部件，既然要考虑到性能、安全、兼容各种数据类型，同时要有一个 Locker 保证临界面，也要满足 FIFO 模型。思来想去，当然自己也实现了几版，最后还是用 golang 自身的 channel 来完成。
- MessageConsumer：用一个 go 协程来执行从 RingBuffer 循环读取，然后往真正的 os.Stdout/os.StdErr/os.File 中输出。（为什么是一个而不是多个？一个速度就足够快了，同时系统底层 io.Writer 自身也带锁，所以一个能减少锁冲撞。）
TIPS： 这里说说为什么我要选择 golang 自身的 channel 作为 CriticalSurface 和 RingBuffer 的实现体：
- channel 是 golang 官方的代码包，有专门的团队对这个代码质量负责。channel 很早就出来了，Bugs 修复的差不多了，非常的稳定可靠。（也有自己懒了，不想自己写 RingBuffer，然后要考虑各种场景的代码测试。）
- channel 的 “<-” 动作天生就有一个 Locker，有非常好的临界面控制。
- channel 底层是就是一个 RingBuffer 的实现，效率非常不错，而且如果 channel 满了，数据投递动作就会卡住，如果 channel 空了，数据提取动作也会被卡住，这个机制非常棒。
- channel 天生就是一个 FIFO 的模型，非常合适做数据缓冲，解决 Producer 和 Consumer 和速度差这样问题。
有了上面的思路，我的代码架构也基本出来了，结构图如下：
这里我贴出一个实现代码（DEMO 测试用，生产要谨慎重新实现）：
const defaultQueueCap = math.MaxUint16 * 8
var QueueIsFullError = errors.New("queue is full")
var DropWriteMessageError = errors.New("message writing failure and drop it")
type Writer struct {
name string
bufferPool *extraBufferPool
writer io.Writer
wg sync.WaitGroup
lock sync.RWMutex
channel chan *extraBuffer
}
func NewBufferWriter(name string, w io.Writer, queueCap uint32) *Writer {
if len(name) <= 0 {
name = "bw_" + utils.GetRandIdString()
}
if queueCap <= 0 {
queueCap = defaultQueueCap
}
if w == nil {
return nil
}
wr := Writer{
name: name,
bufferPool: newExtraBufferPool(defaultBufferSize),
writer: w,
channel: make(chan *extraBuffer, queueCap),
}
wr.wg.Add(1)
go wr.poller(utils.GetRandIdString())
return &wr
}
func (w *Writer) Write(p []byte) (int, error) {
if w.lock.TryRLock() {
defer w.lock.RUnlock()
b := w.bufferPool.Get()
count, err := b.buff.Write(p)
if err != nil {
w.bufferPool.Put(b)
return count, err
}
select {
case w.channel <- b: // channel 内部传递的是 buffer 的指针，速度比传递对象快。
break
default:
w.bufferPool.Put(b)
return count, QueueIsFullError
}
return len(p), nil
} else {
return -1, DropWriteMessageError
}
}
func (w *Writer) Close() {
w.lock.Lock()
close(w.channel)
w.wg.Wait()
w.lock.Unlock()
}
func (w *Writer) poller(id string) {
var (
eb *extraBuffer
err error
)
defer w.wg.Done()
for eb = range w.channel {
_, err = w.writer.Write(eb.buff.Bytes())
if err != nil {
log.Printf("writer: %s, id: %s, error: %s, message: %s", w.name, id,
err.Error(), utils.BytesToString(eb.buff.Bytes()))
}
w.bufferPool.Put(eb)
}
}
然后在 uber-go/zap 中如何使用呢？
import (
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
"os"
"time"
)
func main() {
wr := NewBufferWriter("lee", os.Stdout, 0)
defer wr.Close()
c := zapcore.NewCore(
zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig()),
zapcore.AddSync(wr),
zap.NewAtomicLevelAt(zap.DebugLevel),
)
log := zap.New(c)
log.Info("demo log")
time.Sleep(3 * time.Second) // 这里要稍微等待下，因为是异步的输出，log.Info() 执行完毕，日志并没有完全输出到 console
}
Console 输出：
$ go run asynclog.go
{"level":"info","ts":1674808100.0148869,"msg":"demo log"}
输出结果符合逾期
测试代码
为了验证架构和代码质量，这里做了异步输出日志、同步输出日志和不输出日志 3 种情况下，对 gin 封装的 webservice 框架吞吐力的影响。
| # | 测试内容 | Requests/sec |
|---|---|---|
| 1 | 同步输出日志 | 20074.24 |
| 2 | 异步输出日志 | 64197.08 |
| 3 | 不输出日志 | 65551.84 |
同步输出日志
$ wrk -t 10 -c 1000 http://127.0.0.1:8080/xx/
Running 10s test @ http://127.0.0.1:8080/xx/
10 threads and 1000 connections
Thread Stats Avg Stdev Max +/- Stdev
Latency 12.03ms 14.23ms 202.46ms 89.23%
Req/Sec 2.03k 1.36k 9.49k 59.28%
202813 requests in 10.10s, 100.58MB read
Socket errors: connect 757, read 73, write 0, timeout 0
Requests/sec: 20074.24
Transfer/sec: 9.96MB
异步输出日志
$ wrk -t 10 -c 1000 http://127.0.0.1:8080/xx/
Running 10s test @ http://127.0.0.1:8080/xx/
10 threads and 1000 connections
Thread Stats Avg Stdev Max +/- Stdev
Latency 3.75ms 2.43ms 39.94ms 92.68%
Req/Sec 6.48k 3.86k 14.78k 57.11%
648554 requests in 10.10s, 321.62MB read
Socket errors: connect 757, read 79, write 0, timeout 0
Requests/sec: 64197.08
Transfer/sec: 31.84MB
不输出日志
$ wrk -t 10 -c 1000 http://127.0.0.1:8080/xx/
Running 10s test @ http://127.0.0.1:8080/xx/
10 threads and 1000 connections
Thread Stats Avg Stdev Max +/- Stdev
Latency 3.69ms 505.13us 9.29ms 77.36%
Req/Sec 6.60k 4.25k 15.31k 56.45%
662381 requests in 10.10s, 328.48MB read
Socket errors: connect 757, read 64, write 0, timeout 0
Requests/sec: 65551.84
Transfer/sec: 32.51MB
总结
通过对上面的工程代码测试，基本实现了 gin + zap 的异步日志输出功能的实现。当然上面的代码仅供小伙伴学习研究用，并不能作为生产代码使用。
从结果来看，golang 的 channel 整体性能还是非常不错?；?channel 实现的异步日志输出基本于不输出日志的吞吐力和性能相当。
在实际工作中，我们能用 golang 原生库的时候就尽量用，因为 golang 团队在写库的时候，大多数的情况和场景都考虑过，所以没有必自己做一个轮子。安全！安全！安全！
至于 uber-go/zap 团队为什么不愿意实现这样的异步日志输出模型，可能有他们的想法吧。但是我想，不论那种异步日志模型，都存在着程序异?；岫罩镜那榭?。这里再次提醒小伙伴，要慎重选择日志系统模型，切不可以一味追求速度而忽略日志，因为服务日志也是重要的业务数据。
