事件背景

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

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

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

心智負擔

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

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

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

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

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

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

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

前置知識

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

在動之前還是要準備些知識，還要做好結構設計，這樣才能解答：一套合理的異步輸出模型應該是什么樣的？

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

有的小伙伴看到這個圖覺得有點眼熟？Kafka？不對，不對，不對，還少了一個 Broker。因為這里不需要對 Producer 實現(xiàn)一個獨立的緩沖器和分類器，那么 Broker 這樣的角色就不存在了。

簡單的介紹下成員角色：

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

為什么選擇上面的模型：

• 希望在現(xiàn)有的 uber-go/zap 的結構上擴展，實現(xiàn)一部分能力，滿足功能擴展。
• 不希望重復做輪子，因為輪子做出來，需要有嚴格的代碼測試和壓力測試，才能交付生產(chǎn)系統(tǒng)。
• 模型簡單，好理解，也好實現(xiàn)。
• 性能比較高，而且架構整體比較合理。

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

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

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

解決思路

uber-go/zap 代碼分析

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

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

當然 uber-go/zap 早考慮到這樣的情況，就給一個非常棒的包裝函數(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)把我們希望要做的事情都給做好了，我們只要實現(xià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)
}

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

上手開發(fā)

還是回到上一章中的 5 個核心問題，我想到這里應該有答案了：

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

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

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

有了上面的思路，我的代碼架構也基本出來了，結構圖如下：

這里我貼出一個實現(xiàn)代碼（DEMO 測試用，生產(chǎn)要謹慎重新實現(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 的指針，速度比傳遞對象快。
			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() 執(zhí)行完畢，日志并沒有完全輸出到 console
}

Console 輸出：

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

輸出結果符合逾期

測試代碼

為了驗證架構和代碼質(zhì)量，這里做了異步輸出日志、同步輸出日志和不輸出日志 3 種情況下，對 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

總結

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

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

在實際工作中，我們能用 golang 原生庫的時候就盡量用，因為 golang 團隊在寫庫的時候，大多數(shù)的情況和場景都考慮過，所以沒有必自己做一個輪子。安全！安全！安全！

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

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

最新評論