事件背景

過年在家正好閑得沒有太多事情，想起年前一個(gè)研發(fā)項(xiàng)目負(fù)責(zé)人反饋的問題：“老李啊，我們組一直在使用你這邊的 gin 封裝的 webservice 框架開發(fā)，我們需要一套標(biāo)準(zhǔn)的異步日志輸出模塊。現(xiàn)在組內(nèi)和其他使用 gin 的小伙伴實(shí)現(xiàn)的‘各有千秋’不統(tǒng)一，沒有一個(gè)組或者部門對(duì)這部分的代碼負(fù)責(zé)和長(zhǎng)期維護(hù)。你能不能想想辦法。”

這一看就是掉頭發(fā)的事情，雖然 gin 封裝的 webservice 框架是我開發(fā)底層服務(wù)包，已經(jīng)推廣到公司所有 golang 開發(fā)組使用，現(xiàn)在需要一個(gè)統(tǒng)一異步日志輸出的模塊是否真的有意義，要認(rèn)真的考慮和研究下，畢竟有核心業(yè)務(wù)團(tuán)隊(duì)有這樣的需求。

索性打開了 uber-go/zap 日志框架的源代碼，看看到底是什么原因推動(dòng)大家都要手寫異步日志模塊。不看不知道，一看嚇一跳，項(xiàng)目中 issue#998 就有討論，我看了下 issue 留言，覺得大家的說法都挺正確，而項(xiàng)目作者一直無動(dòng)無衷，而且堅(jiān)信 bufio + 定時(shí) flush 的方式 才是正道，怪不得大家都要自己手寫一個(gè)異步日志輸出模塊。

心智負(fù)擔(dān)

在要寫 uber-go/zap 異步日志模塊之前，首先要明白異步日志模塊的優(yōu)點(diǎn)、缺點(diǎn)以及適用的場(chǎng)景，這樣代碼才寫的有意義，是真正的解決問題和能幫助到小伙伴的。

關(guān)于同步和異步模型的差異，這邊就不展開了，估計(jì)再寫幾千字也不一定能說清楚，有需要深入了解的小伙伴，可以自行 baidu，那里有很多相關(guān)的文章，而且講解得非常清晰。這里我就不需要過多解析，而我需要講的是同步和異步日志模塊。

• 同步日志：日志信息投遞后，必須要等到日志信息寫到對(duì)應(yīng)的 io.Writer 中（os.Stdout, 文件等等）并返回，這個(gè)調(diào)用過程結(jié)束。適合 Warning 級(jí)別以上日志輸出，強(qiáng)記錄或者落盤需求的日志信息，不能丟失。
• 異步日志：日志信息投遞后，調(diào)用過程結(jié)束。而日志信息是否能夠正確寫到對(duì)應(yīng)的 io.Writer 中（os.Stdout, 文件等等）是由異步日志模塊保證，不等待調(diào)用過程。適合 Warning 級(jí)別以下日志輸出，盡量存儲(chǔ)日志，如果沒有存儲(chǔ)，丟失也沒有關(guān)系。

那么我就用一句話說明白這兩種日志模型的差別。

• 同步日志：慢，安全，日志不丟
• 異步日志：快，不安全，日志盡力記錄

既然這里說到是心智負(fù)擔(dān)，但是真正負(fù)擔(dān)在哪里？ 實(shí)際上面已經(jīng)提到了心智負(fù)擔(dān)的核心內(nèi)容：就是如何正確的選擇一個(gè)日志模型。

而我們這邊需求是明確知道有部分日志可以丟失，追求接口響應(yīng)速度，希望有統(tǒng)一的實(shí)現(xiàn)，有人維護(hù)代碼和與整個(gè) gin 封裝的 webservice 框架融合的品質(zhì)。

前置知識(shí)

明確了開發(fā)的需求，開發(fā)的目標(biāo)。確認(rèn)了開發(fā)有意義，確實(shí)能解決問題。那么：就是干!!!

在動(dòng)之前還是要準(zhǔn)備些知識(shí)，還要做好結(jié)構(gòu)設(shè)計(jì)，這樣才能解答：一套合理的異步輸出模型應(yīng)該是什么樣的？

分享下我理解的一個(gè)異步日志模型是什么樣的（歡迎大家來“錘”，但是錘我的時(shí)候，麻煩輕點(diǎn)哈）

有的小伙伴看到這個(gè)圖覺得有點(diǎn)眼熟？Kafka？不對(duì)，不對(duì)，不對(duì)，還少了一個(gè) Broker。因?yàn)檫@里不需要對(duì) Producer 實(shí)現(xiàn)一個(gè)獨(dú)立的緩沖器和分類器，那么 Broker 這樣的角色就不存在了。

簡(jiǎn)單的介紹下成員角色：

• MessageProducer: 消息和數(shù)據(jù)生成者
• CriticalSurface: 并發(fā)臨界面，所有 MessageProducer 都到這邊競(jìng)爭(zhēng)控制權(quán)，往 RingBuffer 中寫入數(shù)據(jù)
• RingBuffer: 消息和數(shù)據(jù)的緩沖（記得緩沖和緩存區(qū)別，這邊用緩沖就是為了解決 Producer 和 Consumer 和速度差）
• MessageConsumer: 消息和數(shù)據(jù)消費(fèi)者

為什么選擇上面的模型：

• 希望在現(xiàn)有的 uber-go/zap 的結(jié)構(gòu)上擴(kuò)展，實(shí)現(xiàn)一部分能力，滿足功能擴(kuò)展。
• 不希望重復(fù)做輪子，因?yàn)檩喿幼龀鰜恚枰袊?yán)格的代碼測(cè)試和壓力測(cè)試，才能交付生產(chǎn)系統(tǒng)。
• 模型簡(jiǎn)單，好理解，也好實(shí)現(xiàn)。
• 性能比較高，而且架構(gòu)整體比較合理。

為了實(shí)現(xiàn)這個(gè)模型，還需要思考如下幾個(gè)問題：

• CriticalSurface 如何實(shí)現(xiàn)？因?yàn)橐獫M足多個(gè) MessageBroker 并發(fā)使用，那么這個(gè)臨界面就必須要做，要不然就出現(xiàn)爭(zhēng)搶資源失控的情況。
• 為什么要選擇 RingBuffer？RingBuffer 是目前速度和效率最好的一種緩沖模型，Linux/Unix 系統(tǒng)中廣泛使用。
• 選擇 RingBuffer 需要注意些什么？RingBuffer 有快慢指針的問題，如果控制不好，快指針就回覆寫慢指針的數(shù)據(jù)，地址數(shù)據(jù)丟失的情況。
• MessageConsumer 數(shù)量如何限制？如何平衡信息的創(chuàng)建與消費(fèi)之間的速度差異。
• 如何支持多種日志方式輸出類型。(golang 多種 io.Writer 模型)

如果看到這里，估計(jì)已經(jīng)勸退了很多的小伙伴，我想這就是為什么那個(gè)研發(fā)項(xiàng)目負(fù)責(zé)人帶著團(tuán)隊(duì)問題來找我，希望能夠得到解決的原因吧。確實(shí)不容易。

解決思路

uber-go/zap 代碼分析

在認(rèn)真看看完了 uber-go/zap 的代碼以后，發(fā)現(xiàn) uber 就是 uber，代碼質(zhì)量還是非常不錯(cuò)的，很多模塊抽象的非常不錯(cuò)。通過一段時(shí)間的思考后，確認(rèn)我們要實(shí)現(xiàn)一個(gè)獨(dú)立的 WriteSyncer, 跟 uber-go/zap 中的 BufferedWriteSyncer 扮演相同的角色。

既然要實(shí)現(xiàn)，我們先看看 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 是一個(gè) interface，也就是我們只要引用 io.Writer 和實(shí)現(xiàn) Sync() error 這樣的一個(gè)方法就可以對(duì)接 uber-go/zap 系統(tǒng)中。那么 Sync() 這個(gè)函數(shù)到底是干嘛的？ 顧名思義就是讓 zap 觸發(fā)數(shù)據(jù)同步動(dòng)作時(shí)需要執(zhí)行的一個(gè)方法。但是我們是異步日志，明顯 uber-go/zap 處理完日志相關(guān)的數(shù)據(jù)，丟給我實(shí)現(xiàn)的 WriteSyncer 以后，就不應(yīng)該在干預(yù)異步日志模塊的后期動(dòng)作了，所以 Sync() 給他一個(gè)空殼函數(shù)就行了。

當(dāng)然 uber-go/zap 早考慮到這樣的情況，就給一個(gè)非常棒的包裝函數(shù) 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 已經(jīng)把我們希望要做的事情都給做好了，我們只要實(shí)現(xiàn)一個(gè)標(biāo)準(zhǔn)的 io.Writer 就行了，那繼續(xù)看 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)
}

哇，好簡(jiǎn)單。要實(shí)現(xiàn) io.Writer 僅僅只要實(shí)現(xiàn)一個(gè) Write(p []byte) (n int, err error) 方法就行了，So Easy !!!!

上手開發(fā)

還是回到上一章中的 5 個(gè)核心問題，我想到這里應(yīng)該有答案了：

• MessageProducer：用一個(gè)函數(shù)實(shí)現(xiàn)，實(shí)際上就是 Write(p []byte)，接收 uber-go/zap 投遞來的消息內(nèi)容。
• CriticalSurface 和 RingBuffer： 是最核心的部件，既然要考慮到性能、安全、兼容各種數(shù)據(jù)類型，同時(shí)要有一個(gè) Locker 保證臨界面，也要滿足 FIFO 模型。思來想去，當(dāng)然自己也實(shí)現(xiàn)了幾版，最后還是用 golang 自身的 channel 來完成。
• MessageConsumer：用一個(gè) go 協(xié)程來執(zhí)行從 RingBuffer 循環(huán)讀取，然后往真正的 os.Stdout/os.StdErr/os.File 中輸出。（為什么是一個(gè)而不是多個(gè)？一個(gè)速度就足夠快了，同時(shí)系統(tǒng)底層 io.Writer 自身也帶鎖，所以一個(gè)能減少鎖沖撞。）

TIPS： 這里說說為什么我要選擇 golang 自身的 channel 作為 CriticalSurface 和 RingBuffer 的實(shí)現(xiàn)體：

• channel 是 golang 官方的代碼包，有專門的團(tuán)隊(duì)對(duì)這個(gè)代碼質(zhì)量負(fù)責(zé)。channel 很早就出來了，Bugs 修復(fù)的差不多了，非常的穩(wěn)定可靠。（也有自己懶了，不想自己寫 RingBuffer，然后要考慮各種場(chǎng)景的代碼測(cè)試。）
• channel 的 “<-” 動(dòng)作天生就有一個(gè) Locker，有非常好的臨界面控制。
• channel 底層是就是一個(gè) RingBuffer 的實(shí)現(xiàn)，效率非常不錯(cuò)，而且如果 channel 滿了，數(shù)據(jù)投遞動(dòng)作就會(huì)卡住，如果 channel 空了，數(shù)據(jù)提取動(dòng)作也會(huì)被卡住，這個(gè)機(jī)制非常棒。
• channel 天生就是一個(gè) FIFO 的模型，非常合適做數(shù)據(jù)緩沖，解決 Producer 和 Consumer 和速度差這樣問題。

有了上面的思路，我的代碼架構(gòu)也基本出來了，結(jié)構(gòu)圖如下：

這里我貼出一個(gè)實(shí)現(xiàn)代碼（DEMO 測(cè)試用，生產(chǎn)要謹(jǐn)慎重新實(shí)現(xiàn)）：

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 內(nèi)部傳遞的是 buffer 的指針，速度比傳遞對(duì)象快。
			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) // 這里要稍微等待下，因?yàn)槭钱惒降妮敵?，log.Info() 執(zhí)行完畢，日志并沒有完全輸出到 console
}

Console 輸出：

$ go run asynclog.go
{"level":"info","ts":1674808100.0148869,"msg":"demo log"}

輸出結(jié)果符合逾期

測(cè)試代碼

為了驗(yàn)證架構(gòu)和代碼質(zhì)量，這里做了異步輸出日志、同步輸出日志和不輸出日志 3 種情況下，對(duì) gin 封裝的 webservice 框架吞吐力的影響。

同步輸出日志

$ 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

總結(jié)

通過對(duì)上面的工程代碼測(cè)試，基本實(shí)現(xiàn)了 gin + zap 的異步日志輸出功能的實(shí)現(xiàn)。當(dāng)然上面的代碼僅供小伙伴學(xué)習(xí)研究用，并不能作為生產(chǎn)代碼使用。

從結(jié)果來看，golang 的 channel 整體性能還是非常不錯(cuò)。基于 channel 實(shí)現(xiàn)的異步日志輸出基本于不輸出日志的吞吐力和性能相當(dāng)。

在實(shí)際工作中，我們能用 golang 原生庫的時(shí)候就盡量用，因?yàn)?golang 團(tuán)隊(duì)在寫庫的時(shí)候，大多數(shù)的情況和場(chǎng)景都考慮過，所以沒有必自己做一個(gè)輪子。安全！安全！安全！

至于 uber-go/zap 團(tuán)隊(duì)為什么不愿意實(shí)現(xiàn)這樣的異步日志輸出模型，可能有他們的想法吧。但是我想，不論那種異步日志模型，都存在著程序異常會(huì)丟日志的情況。這里再次提醒小伙伴，要慎重選擇日志系統(tǒng)模型，切不可以一味追求速度而忽略日志，因?yàn)榉?wù)日志也是重要的業(yè)務(wù)數(shù)據(jù)。

以上就是uber go zap 日志框架支持異步日志輸出的詳細(xì)內(nèi)容，更多關(guān)于uber go zap日志異步輸出的資料請(qǐng)關(guān)注腳本之家其它相關(guān)文章！

最新評(píng)論