Go 日誌庫 zero-log 大解剖
我是一隻可愛的土撥鼠,專注於分享 Go 職場、招聘和求職,解 Gopher 之憂!歡迎關注我。
歡迎大家加入 Go 招聘交流羣,來這裏找志同道合的小夥伴!跟土撥鼠們一起交流學習。
-
什麼是 zerolog ?
-
使用 zerolog
-
安裝
-
Contextual Logger
-
多級 Logger
-
注意事項
-
瞭解源碼
-
看一下 Logger 結構體
-
debug 瞭解輸出日誌流程
-
從 zerolog 學習避免內存分配
-
學習日誌級別
-
學習如何實現 Hook
-
學習如何得到調用者函數名
-
從日誌採樣中學習 atomic
-
Doc
-
比較
-
相似的庫
-
參考資料
文章可能相對較長,請耐心看完。定有收穫。
什麼是 zerolog ?
zerolog 包提供了一個專門用於 JSON 輸出的簡單快速的 Logger。
zerolog 的 API 旨在爲開發者提供出色的體驗和令人驚歎的性能 [1]。其獨特的鏈式 API 允許通過避免內存分配和反射來寫入 JSON (或 CBOR) 日誌。
uber 的 zap[2] 庫開創了這種方法,zerolog 通過更簡單的應用編程接口和更好的性能,將這一概念提升到了更高的層次。
使用 zerolog
安裝
go get -u github.com/rs/zerolog/log
Contextual Logger
func TestContextualLogger(t *testing.T) {
log := zerolog.New(os.Stdout)
log.Info().Str("content", "Hello world").Int("count", 3).Msg("TestContextualLogger")
// 添加上下文 (文件名/行號/字符串)
log = log.With().Caller().Str("foo", "bar").Logger()
log.Info().Msg("Hello wrold")
}
輸出
// {"level":"info","content":"Hello world","count":3,"message":"TestContextualLogger"}
// {"level":"info","caller":"log_example_test.go:29","message":"Hello wrold"}
與 zap 相同的是,都定義了強類型字段,你可以在這裏 [3] 找到支持字段的完整列表。
與 zap 不同的是,zerolog 採用鏈式調用。
多級 Logger
zerolog 提供了從 Trace 到 Panic 七個級別
// 設置日誌級別
zerolog.SetGlobalLevel(zerolog.WarnLevel)
log.Trace().Msg("Trace")
log.Debug().Msg("Debug")
log.Info().Msg("Info")
log.Warn().Msg("Warn")
log.Error().Msg("Error")
log.Log().Msg("沒有級別")
輸出
{"level":"warn","message":"Warn"}
{"level":"error","message":"Error"}
{"message":"沒有級別"}
注意事項
1.zerolog 不會對重複的字段刪除
logger := zerolog.New(os.Stderr).With().Timestamp().Logger()
logger.Info().
Timestamp().
Msg("dup")
輸出
{"level":"info","time":1494567715,"time":1494567715,"message":"dup"}
-
鏈式調用必須調用 Msg 或 Msgf,Send 才能輸出日誌,Send 相當於調用 Msg("")
-
一旦調用 Msg ,Event 將會被處理 (放回池中或丟掉),不允許二次調用。
瞭解源碼
本次 zerolog 的源碼分析基於 zerolog 1.22.0 版本,源碼分析較長,希望大家耐心看完。希望大家能有所收穫。
看一下 Logger 結構體
Logger 的參數 w 類型是 LevelWriter 接口,用於向目標輸出事件。zerolog.New 函數用來創建 Logger,看下方源碼。
// ============ log.go ===
type Logger struct {
w LevelWriter // 輸出對象
level Level // 日誌級別
sampler Sampler // 採樣器
context []byte // 存儲上下文
hooks []Hook
stack bool
}
func New(w io.Writer) Logger {
if w == nil {
// ioutil.Discard 所有成功執行的 Write 操作都不會產生任何實際的效果
w = ioutil.Discard
}
lw, ok := w.(LevelWriter)
// 傳入的不是 LevelWriter 類型,封裝成此類型
if !ok {
lw = levelWriterAdapter{w}
}
// 默認輸出日誌級別 TraceLevel
return Logger{w: lw, level: TraceLevel}
}
debug 瞭解輸出日誌流程
image-20210615150059405
如上圖所示,在第三行打上斷點。
下圖表示該行代碼執行流程。
開始 debug
// ============ log.go ===
// Info 開始記錄一條 info 級別的消息
// 你必須在返回的 *Event 上調用 Msg 才能發送事件
func (l *Logger) Info() *Event {
return l.newEvent(InfoLevel, nil)
}
func (l *Logger) newEvent(level Level, done func(string)) *Event {
// 判斷是否應該記錄的級別
enabled := l.should(level)
if !enabled {
return nil
}
// 創建記錄日誌的對象
e := newEvent(l.w, level)
// 設置 done 函數
e.done = done
// 設置 hook 函數
e.ch = l.hooks
// 記錄日誌級別
if level != NoLevel && LevelFieldName != "" {
e.Str(LevelFieldName, LevelFieldMarshalFunc(level))
}
// 記錄上下文
if l.context != nil && len(l.context) > 1 {
e.buf = enc.AppendObjectData(e.buf, l.context)
}
// 堆棧跟蹤
if l.stack {
e.Stack()
}
return e
}
should 函數用於判斷是否需要記錄本次消息。
// ============ log.go ===
// should 如果應該被記錄,則返回 true
func (l *Logger) should(lvl Level) bool {
if lvl < l.level || lvl < GlobalLevel() {
return false
}
// 採樣後面講
if l.sampler != nil && !samplingDisabled() {
return l.sampler.Sample(lvl)
}
return true
}
newEvent 函數使用 sync.Pool 獲取 Event 對象,並將 Event 參數初始化:日誌級別 level 和寫入對象 LevelWriter。
// ============ event.go ===
// 表示一個日誌事件
type Event struct {
buf []byte // 消息
w LevelWriter // 待寫入的目標接口
level Level // 日誌級別
done func(msg string) // msg 函數結束事件
stack bool // 錯誤堆棧跟蹤
ch []Hook // hook 函數組
skipFrame int
}
func newEvent(w LevelWriter, level Level) *Event {
e := eventPool.Get().(*Event)
e.buf = e.buf[:0]
e.ch = nil
// 在開始添加左大括號 '{'
e.buf = enc.AppendBeginMarker(e.buf)
e.w = w
e.level = level
e.stack = false
e.skipFrame = 0
return e
}
Str 函數是負責將鍵值對添加到 buf,字符串類型添加到 JSON 格式,涉及到特殊字符編碼問題,如果是特殊字符,調用 appendStringComplex 函數解決。
// ============ event.go ===
func (e *Event) Str(key, val string) *Event {
if e == nil {
return e
}
e.buf = enc.AppendString(enc.AppendKey(e.buf, key), val)
return e
}
// ============ internal/json/base.go ===
type Encoder struct{}
// 添加一個新 key
func (e Encoder) AppendKey(dst []byte, key string) []byte {
// 非第一個參數,加個逗號
if dst[len(dst)-1] != '{' {
dst = append(dst, ',')
}
return append(e.AppendString(dst, key), ':')
}
// === internal/json/string.go ===
func (Encoder) AppendString(dst []byte, s string) []byte {
// 雙引號起
dst = append(dst, '"')
// 遍歷字符
for i := 0; i < len(s); i++ {
// 檢查字符是否需要編碼
if !noEscapeTable[s[i]] {
dst = appendStringComplex(dst, s, i)
return append(dst, '"')
}
}
// 不需要編碼的字符串,添加到 dst
dst = append(dst, s...)
// 雙引號收
return append(dst, '"')
}
Int 函數將鍵值 (int 類型) 對添加到 buf,內部調用 strconv.AppendInt 函數實現。
// ============ event.go ===
func (e *Event) Int(key string, i int) *Event {
if e == nil {
return e
}
e.buf = enc.AppendInt(enc.AppendKey(e.buf, key), i)
return e
}
// === internal/json/types.go ===
func (Encoder) AppendInt(dst []byte, val int) []byte {
// 添加整數
return strconv.AppendInt(dst, int64(val), 10)
}
Msg 函數
// === event.go ===
// Msg 是對 msg 的封裝調用,當指針接收器爲 nil 返回
func (e *Event) Msg(msg string) {
if e == nil {
return
}
e.msg(msg)
}
// msg
func (e *Event) msg(msg string) {
// 運行 hook
for _, hook := range e.ch {
hook.Run(e, e.level, msg)
}
// 記錄消息
if msg != "" {
e.buf = enc.AppendString(enc.AppendKey(e.buf, MessageFieldName), msg)
}
// 判斷不爲 nil,則使用 defer 調用 done 函數
if e.done != nil {
defer e.done(msg)
}
// 寫入日誌
if err := e.write(); err != nil {
if ErrorHandler != nil {
ErrorHandler(err)
} else {
fmt.Fprintf(os.Stderr, "zerolog: could not write event: %v\n", err)
}
}
}
// 寫入日誌
func (e *Event) write() (err error) {
if e == nil {
return nil
}
if e.level != Disabled {
// 大括號收尾
e.buf = enc.AppendEndMarker(e.buf)
// 換行
e.buf = enc.AppendLineBreak(e.buf)
// 向目標寫入日誌
if e.w != nil {
// 這裏傳遞的日誌級別,函數內並沒有使用
_, err = e.w.WriteLevel(e.level, e.buf)
}
}
// 將對象放回池中
putEvent(e)
return
}
// === writer.go ===
func (lw levelWriterAdapter) WriteLevel(l Level, p []byte) (n int, err error) {
return lw.Write(p)
}
以上 debug 讓我們對日誌記錄流程有了大概的認識,接下來擴充一下相關知識。
從 zerolog 學習避免內存分配
每一條日誌都會產生一個 *Event 對象 ,當多個 Goroutine 操作日誌,導致創建的對象數目劇增,進而導致 GC 壓力增大。形成 "併發大 - 佔用內存大 - GC 緩慢 - 處理併發能力降低 - 併發更大" 這樣的惡性循環。在這個時候,需要有一個對象池,程序不再自己單獨創建對象,而是從對象池中獲取。
使用 sync.Pool
可以將暫時不用的對象緩存起來,下次需要的時候從池中取,不用再次經過內存分配。
下面代碼中 putEvent 函數,當對象中記錄消息的 buf 不超過 64KB 時,放回池中。這裏有個鏈接,通過這個 issue 23199[4] 瞭解到使用動態增長的 buffer 會導致大量內存被固定,在活鎖的情況下永遠不會釋放。
var eventPool = &sync.Pool{
New: func() interface{} {
return &Event{
buf: make([]byte, 0, 500),
}
},
}
func putEvent(e *Event) {
// 選擇佔用較小內存的 buf,將對象放回池中
// See https://golang.org/issue/23199
const maxSize = 1 << 16 // 64KiB
if cap(e.buf) > maxSize {
return
}
eventPool.Put(e)
}
學習日誌級別
下面代碼中,包含了日誌級別類型的定義,日誌級別對應的字符串值,獲取字符串值的方法以及解析字符串爲日誌級別類型的方法。
// ============= log.go ===
// 日誌級別類型
type Level int8
// 定義所有日誌級別
const (
DebugLevel Level = iota
InfoLevel
WarnLevel
ErrorLevel
FatalLevel
PanicLevel
NoLevel
Disabled
TraceLevel Level = -1
)
// 返回當前級別的 value
func (l Level) String() string {
switch l {
case TraceLevel:
return LevelTraceValue
case DebugLevel:
return LevelDebugValue
case InfoLevel:
return LevelInfoValue
case WarnLevel:
return LevelWarnValue
case ErrorLevel:
return LevelErrorValue
case FatalLevel:
return LevelFatalValue
case PanicLevel:
return LevelPanicValue
case Disabled:
return "disabled"
case NoLevel:
return ""
}
return ""
}
// ParseLevel 將級別字符串解析成 zerolog level value
// 當字符串不匹配任何已知級別,返回錯誤
func ParseLevel(levelStr string) (Level, error) {
switch levelStr {
case LevelFieldMarshalFunc(TraceLevel):
return TraceLevel, nil
case LevelFieldMarshalFunc(DebugLevel):
return DebugLevel, nil
case LevelFieldMarshalFunc(InfoLevel):
return InfoLevel, nil
case LevelFieldMarshalFunc(WarnLevel):
return WarnLevel, nil
case LevelFieldMarshalFunc(ErrorLevel):
return ErrorLevel, nil
case LevelFieldMarshalFunc(FatalLevel):
return FatalLevel, nil
case LevelFieldMarshalFunc(PanicLevel):
return PanicLevel, nil
case LevelFieldMarshalFunc(Disabled):
return Disabled, nil
case LevelFieldMarshalFunc(NoLevel):
return NoLevel, nil
}
return NoLevel, fmt.Errorf("Unknown Level String: '%s', defaulting to NoLevel", levelStr)
}
// ============= globals.go ===
var (
// ......
// 級別字段的 key 名稱
LevelFieldName = "level"
// 各個級別的 value
LevelTraceValue = "trace"
LevelDebugValue = "debug"
LevelInfoValue = "info"
LevelWarnValue = "warn"
LevelErrorValue = "error"
LevelFatalValue = "fatal"
LevelPanicValue = "panic"
// 返回形參級別的 value
LevelFieldMarshalFunc = func(l Level) string {
return l.String()
}
// ......
)
全局日誌級別參數
這裏使用 atomic 來保證原子操作,要麼都執行,要麼都不執行,外界不會看到只執行到一半的狀態,原子操作由底層硬件支持,通常比鎖更有效率。
atomic.StoreInt32 用於存儲 int32 類型的值。
atomic.LoadInt32 用於讀取 int32 類型的值。
在源碼中,做級別判斷時,多處調用 GlobalLevel 以保證併發安全。
// ============= globals.go ===
var (
gLevel = new(int32)
// ......
)
// SetGlobalLevel 設置全局日誌級別
// 要全局禁用日誌,入參爲 Disabled
func SetGlobalLevel(l Level) {
atomic.StoreInt32(gLevel, int32(l))
}
// 返回當前全局日誌級別
func GlobalLevel() Level {
return Level(atomic.LoadInt32(gLevel))
}
學習如何實現 Hook
首先定義 Hook 接口,內部有一個 Run 函數,入參包含 *Event,日誌級別 **level 和消息 (Msg 函數的參數)。
然後定義了 LevelHook 結構體,用於爲每個級別設置 Hook 。
// ============= hook.go ===
// hook 接口
type Hook interface {
Run(e *Event, level Level, message string)
}
// HookFunc 函數適配器
type HookFunc func(e *Event, level Level, message string)
// Run 實現 Hook 接口.
func (h HookFunc) Run(e *Event, level Level, message string) {
h(e, level, message)
}
// 爲每個級別應用不同的 hook
type LevelHook struct {
NoLevelHook, TraceHook, DebugHook, InfoHook, WarnHook, ErrorHook, FatalHook, PanicHook Hook
}
// Run 實現 Hook 接口
func (h LevelHook) Run(e *Event, level Level, message string) {
switch level {
case TraceLevel:
if h.TraceHook != nil {
h.TraceHook.Run(e, level, message)
}
case DebugLevel:
if h.DebugHook != nil {
h.DebugHook.Run(e, level, message)
}
case InfoLevel:
if h.InfoHook != nil {
h.InfoHook.Run(e, level, message)
}
case WarnLevel:
if h.WarnHook != nil {
h.WarnHook.Run(e, level, message)
}
case ErrorLevel:
if h.ErrorHook != nil {
h.ErrorHook.Run(e, level, message)
}
case FatalLevel:
if h.FatalHook != nil {
h.FatalHook.Run(e, level, message)
}
case PanicLevel:
if h.PanicHook != nil {
h.PanicHook.Run(e, level, message)
}
case NoLevel:
if h.NoLevelHook != nil {
h.NoLevelHook.Run(e, level, message)
}
}
}
// NewLevelHook 創建一個 LevelHook
func NewLevelHook() LevelHook {
return LevelHook{}
}
在源碼中是如何使用的?
定義 PrintMsgHook 結構體並實現 Hook 接口,作爲參數傳遞給 log.Hook 函數,Logger 內部的 hooks 參數用來保存對象。
// 使用案例
type PrintMsgHook struct{}
// 實現 Hook 接口,用來向控制檯輸出 msg
func (p PrintMsgHook) Run(e *zerolog.Event, l zerolog.Level, msg string) {
fmt.Println(msg)
}
func TestContextualLogger(t *testing.T) {
log := zerolog.New(os.Stdout)
log = log.Hook(PrintMsgHook{})
log.Info().Msg("TestContextualLogger")
}
添加 hook 源碼如下
// ============ log.go ===
// Hook 返回一個帶有 hook 的 Logger
func (l Logger) Hook(h Hook) Logger {
l.hooks = append(l.hooks, h)
return l
}
輸出日誌必須調用 msg 函數,hook 將在此函數的開頭執行。
// ============ event.go ===
// msg 函數用來運行 hook
func (e *Event) msg(msg string) {
for _, hook := range e.ch {
hook.Run(e, e.level, msg)
}
// .......
// 寫入日誌,此函數上面已經介紹過,此處省略
// .......
}
學習如何得到調用者函數名
在看 zerolog 源碼之前,需要知道一些關於 runtime.Caller 函數的前置知識,
-
runtime.Caller 可以獲取相關調用 goroutine 堆棧上的函數調用的文件和行號信息。
-
參數 skip 是堆棧幀的數量,當 skip=0 時,輸出當前函數信息; 當 skip=1 時,輸出調用棧上一幀,即調用函數者的信息。
-
返回值爲 程序計數器,文件位置,行號,是否能恢復信息
// ============ go@1.16.5 runtime/extern.go ===
func Caller(skip int) (pc uintptr, file string, line int, ok bool) {
rpc := make([]uintptr, 1)
n := callers(skip+1, rpc[:])
if n < 1 {
return
}
frame, _ := CallersFrames(rpc).Next()
return frame.PC, frame.File, frame.Line, frame.PC != 0
}
再看 zerolog 源碼,定義 callerHook 結構體並實現了 Hook 接口,實現函數中調用了參數 *Event 提供的 caller 函數。
其中入參爲預定義參數 CallerSkipFrameCount 和 contextCallerSkipFrameCount ,值都爲 2。
zerolog caller 調用示意圖
// ============ context.go ===
type callerHook struct {
callerSkipFrameCount int
}
func newCallerHook(skipFrameCount int) callerHook {
return callerHook{callerSkipFrameCount: skipFrameCount}
}
func (ch callerHook) Run(e *Event, level Level, msg string) {
switch ch.callerSkipFrameCount {
// useGlobalSkipFrameCount 是 int32 類型最小值
case useGlobalSkipFrameCount:
// CallerSkipFrameCount 預定義全局變量,值爲 2
// contextCallerSkipFrameCount 預定義變量,值爲 2
e.caller(CallerSkipFrameCount + contextCallerSkipFrameCount)
default:
e.caller(ch.callerSkipFrameCount + contextCallerSkipFrameCount)
}
}
// useGlobalSkipFrameCount 值:-2147483648
const useGlobalSkipFrameCount = math.MinInt32
// 創建默認 callerHook
var ch = newCallerHook(useGlobalSkipFrameCount)
// Caller 爲 Logger 添加 hook ,該 hook 用於記錄函數調用者的 file:line
func (c Context) Caller() Context {
c.l = c.l.Hook(ch)
return c
}
// ============ event.go ===
func (e *Event) caller(skip int) *Event {
if e == nil {
return e
}
_, file, line, ok := runtime.Caller(skip + e.skipFrame)
if !ok {
return e
}
// CallerFieldName是默認的 key 名
// CallerMarshalFunc 函數用於拼接 file:line
e.buf = enc.AppendString(enc.AppendKey(e.buf, CallerFieldName), CallerMarshalFunc(file, line))
return e
}
從日誌採樣中學習 atomic
這個使用案例中,TestSample 每秒允許 記錄 5 條消息,超過則每 20 條僅記錄一條
func TestSample(t *testing.T) {
sampled := log.Sample(&zerolog.BurstSampler{
Burst: 5,
Period: 1 * time.Second,
NextSampler: &zerolog.BasicSampler{N: 20},
})
for i := 0; i <= 50; i++ {
sampled.Info().Msgf("logged messages : %2d ", i)
}
}
輸出結果本來應該輸出 50 條日誌,使用了採樣,在一秒內輸出最大 5 條日誌,當大於 5 條後,每 20 條日誌輸出一次。
image-20210618114636900
採樣的流程示意圖如下
zerolog 採樣函數說明圖
下方是定義採樣接口及實現函數的源碼。
在 inc 函數中,使用 atomic 包將競爭的接收器對象的參數變成局部變量,是學習 atomic 很好的實例。函數說明都寫在註釋裏。
// =========== sampler.go ===
// 採樣器接口
type Sampler interface {
// 如果事件是樣本的一部分返回 true
Sample(lvl Level) bool
}
// BasicSampler 基本採樣器
// 每 N 個事件發送一次,不考慮日誌級別
type BasicSampler struct {
N
counter uint32
}
// 實現採樣器接口
func (s *BasicSampler) Sample(lvl Level) bool {
n := s.N
if n == 1 {
return true
}
c := atomic.AddUint32(&s.counter, 1)
return c%n == 1
}
type BurstSampler struct {
// 調用 NextSampler 之前每個時間段(Period)調用的最大事件數量
Burst uint32
// 如果爲 0,則始終調用 NextSampler
Period time.Duration
// 採樣器
NextSampler Sampler
// 用於計數在一定時間內(Period)的調用數量
counter uint32
// 時間段的結束時間(納秒),即 當前時間+Period
resetAt int64
}
// 實現 Sampler 接口
func (s *BurstSampler) Sample(lvl Level) bool {
// 當設置了 Burst 和 Period,大於零時限制 一定時間內的最大事件數量
if s.Burst > 0 && s.Period > 0 {
if s.inc() <= s.Burst {
return true
}
}
// 沒有采樣器,結束
if s.NextSampler == nil {
return false
}
// 調用採樣器
return s.NextSampler.Sample(lvl)
}
func (s *BurstSampler) inc() uint32 {
// 當前時間 (納秒)
now := time.Now().UnixNano()
// 重置時間 (納秒)
resetAt := atomic.LoadInt64(&s.resetAt)
var c uint32
// 當前時間 > 重置時間
if now > resetAt {
c = 1
// 重置 s.counter 爲 1
atomic.StoreUint32(&s.counter, c)
// 計算下一次的重置時間
newResetAt := now + s.Period.Nanoseconds()
// 比較函數開頭獲取的重置時間與存儲的時間是否相等
// 相等時,將下一次的重置時間存儲到 s.resetAt,並返回 true
reset := atomic.CompareAndSwapInt64(&s.resetAt, resetAt, newResetAt)
if !reset {
// 在上面比較賦值那一步沒有搶到的 goroutine 計數器+1
c = atomic.AddUint32(&s.counter, 1)
}
} else {
c = atomic.AddUint32(&s.counter, 1)
}
return c
}
在代碼中如何調用的呢?
Info 函數及其他級別函數都會調用 newEvent,在該函數的開頭, should 函數用來判斷是否需要記錄的日誌級別和採樣。
// ============ log.go ===
// should 如果應該被記錄,則返回 true
func (l *Logger) should(lvl Level) bool {
if lvl < l.level || lvl < GlobalLevel() {
return false
}
// 如果使用了採樣,則調用採樣函數,判斷本次事件是否記錄
if l.sampler != nil && !samplingDisabled() {
return l.sampler.Sample(lvl)
}
return true
}
Doc
關於更多 zerolog 的使用可以參考 https://pkg.go.dev/github.com/rs/zerolog
比較
說明 : 以下資料來源於 zerolog 官方。從性能分析上 zerolog 比 zap 和其他 logger 庫更勝一籌,關於 zerolog 和 zap 的使用,gopher 可根據實際業務場景具體考量。
記錄 10 個 KV 字段的消息 :
使用一個已經有 10 個 KV 字段的 logger 記錄一條消息 :
記錄一個字符串,沒有字段或 printf
風格的模板 :
相似的庫
logrus[5] 功能強大
zap[6] 非常快速,結構化,分級
參考資料
zerolog 官方文檔 [7]
參考資料
[1] 性能: https://github.com/rs/zerolog#benchmarks
[2] zap: https://godoc.org/go.uber.org/zap
[3] 這裏: https://pkg.go.dev/github.com/rs/zerolog#readme-standard-types
[4] issue 23199: https://golang.org/issue/23199
[5] logrus: https://github.com/sirupsen/logrus
[6] zap: https://github.com/uber-go/zap
[7] zerolog 官方文檔: https://pkg.go.dev/github.com/rs/zerolog
本文由 Readfog 進行 AMP 轉碼,版權歸原作者所有。
來源:https://mp.weixin.qq.com/s/knayd7gQSChyDfSJCxh3uA