golang log4go的日志輸出優(yōu)化詳解

前言

在go語言中，自身已經(jīng)集成了一定log模塊，開發(fā)者可以使用go語言自身的log包(import “l(fā)og”) 。也有不少對(duì)自身log的開源封裝。對(duì)于一些簡單的開發(fā)，自身的log模塊就已經(jīng)足夠應(yīng)付。但是對(duì)一些大型，復(fù)雜的開發(fā)，log需要分門別類的輸出，或者通過網(wǎng)絡(luò)進(jìn)行輸出，自身log模塊將難以應(yīng)對(duì)。

當(dāng)前也有一些比較重量級(jí)的log模塊，比如logrus，可以實(shí)現(xiàn)比較復(fù)雜的功能。這里介紹一個(gè)輕量級(jí)的log模塊——log4go

最近又看了一些golang的日志包和相關(guān)的文章，仔細(xì)閱讀了go 1.9.2系統(tǒng)提供的log和go-log，產(chǎn)生了對(duì)log4go的日志輸出進(jìn)行優(yōu)化的想法。

結(jié)構(gòu)化與multiwriter

log使用multiwriter支持多個(gè)日志輸出，用 Mutex 加鎖解決多線程日志輸出的沖突。log4go 則采用結(jié)構(gòu)化編程用 channel 傳遞 LogRecord 日志記錄。

原來以為 channel 的效率比較高……其實(shí)這是一個(gè)偽命題。channel 是一個(gè)全局加鎖的隊(duì)列，可以用來加鎖，但效率比較低。因?yàn)樗嗔藗鬟f數(shù)據(jù)、協(xié)調(diào)順序處理、timout等功能，并不僅僅是加鎖。跟Mutex不是一回事兒。

log4go 將屏幕日志輸出 termlog 放在了結(jié)構(gòu)里，這帶來一個(gè)小問題。當(dāng)我們用log4go調(diào)試小程序時(shí)，運(yùn)行的太快，termlog 的 goroutine 還沒有運(yùn)行起來，程序就退出了。結(jié)果屏幕上沒有顯示日志。這個(gè)問題只能通過在 Close() 時(shí)加延時(shí)，等待 goroutine 啟動(dòng)來解決。然后還要檢查 channel ……

func (f *Filter) Close() {
 if f.closed {
  return
 }
 // sleep at most one second and let go routine running
 // drain the log channel before closing
 for i := 10; i > 0; i-- {
  // Must call Sleep here, otherwise, may panic send on closed channel
  time.Sleep(100 * time.Millisecond)
  if len(f.rec) = 0 {
   break
  }
 }
 // block write channel
 f.closed = true
 defer f.LogWriter.Close()
 close(f.rec)
 if len(f.rec) = 0 {
  return
 }
 // drain the log channel and write driect
 for rec := range f.rec {
  f.LogWrite(rec)
 }
}

log直接將格式化日志信息輸出到屏幕，簡單多了。

試著兼顧兩者，在 log4go 中增加了 writer，直接輸出到屏幕。擬將FileLog，SocketLog作為backend，仍然放在結(jié)構(gòu)里。這樣，調(diào)試小程序和生產(chǎn)程序可以使用同一個(gè)日志庫。實(shí)測效率略有降低。不知道 windows 下的 ColorLog 如何，以后再說。

在log4go中可以通過調(diào)用 SetOutput(nil) ，使out = nil 來關(guān)閉屏幕輸出。

Determine caller func - it's expensive

這句話注釋在 log 源文件中，log4go也要調(diào)用runtime.Caller(skip int)函數(shù)來獲取源文件名和行號(hào)。它是昂貴的——消耗了CPU。建議在生產(chǎn)環(huán)境中關(guān)閉，log.SetSkip(-1) 。如果要對(duì)log4go進(jìn)行封裝，設(shè)置 log.SetSkip(log.GetSkip()+1) 。

format優(yōu)化

其實(shí)，這才是文章的主題。

日志輸出避免不了打印日期和時(shí)間，linux 環(huán)境下還要打印微秒，說不定還要打印時(shí)區(qū)。log4go的pattlog.go就是完成這些工作的。

• 有一個(gè)1秒更新一次的cache機(jī)制。很漂亮。
• 大量使用字符串格式化函數(shù)——fmt.Sprintf。
• 返回字符串。而writer一般支持的是[]byte。多做一次轉(zhuǎn)換。
• 每次都bytes.Splite講format字符串以%字符分解成[][]byte。

在log里邊自備了一個(gè)cheap的itoa函數(shù)。

// Cheap integer to fixed-width decimal ASCII. Give a negative width to avoid zero-padding.
func itoa(buf *[]byte, i int, wid int) {
 // Assemble decimal in reverse order.
 var b [20]byte
 bp := len(b) - 1
 for i >= 10 || wid > 1 {
  wid--
  q := i / 10
  b[bp] = byte('0' + i - q*10)
  bp--
  i = q
 }
 // i  10
 b[bp] = byte('0' + i)
 *buf = append(*buf, b[bp:]...)
}

用這個(gè)函數(shù)替換日期和時(shí)間的字符串格式化函數(shù)。用[]byte代替string。

優(yōu)化前，log4go 的 benchmark。

BenchmarkFormatLogRecord-4    300000    4480 ns/op
BenchmarkConsoleLog-4     1000000    1748 ns/op
BenchmarkConsoleNotLogged-4    20000000    97.5 ns/op
BenchmarkConsoleUtilLog-4     300000    3496 ns/op
BenchmarkConsoleUtilNotLog-4   20000000    104 ns/op

優(yōu)化后：

BenchmarkFormatLogRecord-4  1000000    1443 ns/op
BenchmarkConsoleLog-4   2000000    982 ns/op
BenchmarkConsoleUtilLog-4   500000    3242 ns/op
BenchmarkConsoleUtilNotLog-4 30000000    48.4 ns/op

格式化日期時(shí)間所花的時(shí)間是原來的1/3。

打印無格式化信息所花的時(shí)間是原來的1/2。

BenchmarkConsoleUtilLog調(diào)用了runtime.Caller，格式化信息，且新增了輸出信息到屏幕的時(shí)間。

字符串格式化——比較昂貴。

總結(jié)

以上就是這篇文章的全部內(nèi)容了，希望本文的內(nèi)容對(duì)大家的學(xué)習(xí)或者工作具有一定的參考學(xué)習(xí)價(jià)值，如果有疑問大家可以留言交流，謝謝大家對(duì)腳本之家的支持。