Go日誌，打印源碼文件名和行號形成的性能開銷

日誌中打印源碼文件名和行號，是很是實用的功能，尤爲是開發階段的debug日誌，能夠快速經過日誌找到對應的源碼位置。

Go標準庫中的package log也支持打印源碼文件名和行號，打開方式是設置如下兩個標誌中的任意一個：

Llongfile    // full file name and line number: /a/b/c/d.go:23
Lshortfile   // final file name element and line number: d.go:23. overrides Llongfile

標準庫中全部的日誌打印最後都要調用Output函數，再在裏面調用runtime.Caller獲取源碼文件名和行號：

// package log
func (l *Logger) Output(calldepth int, s string) error

// package runtime
func Caller(skip int) (pc uintptr, file string, line int, ok bool)

runtime.Caller獲取源碼文件名和行號的方式，是經過查詢調用堆棧的信息獲得的，這也是爲何調用方須要傳入獲取棧的層數，也即skip參數。

而Go中的調用棧，和runtime協程管理棧幀相關。我沒有系統學習過這部份內容，因此就不展開分析了，咱們直接benchmark數聽說話。

先直接對runtime.Caller作benchmark：

//BenchmarkRuntimeCaller-4         2417739           488 ns/op         216 B/op           2 allocs/op
func BenchmarkRuntimeCaller(b *testing.B) {
    for n := 0; n < b.N; n++ {
        runtime.Caller(0)
    }
}

單次大概是500納秒左右的耗時。咱們將skip參數從0增大到2：

//BenchmarkRuntimeCaller2-4        1213971           983 ns/op         216 B/op           2 allocs/op
func BenchmarkRuntimeCaller2(b *testing.B) {
    for n := 0; n < b.N; n++ {
        runtime.Caller(2)
    }
}

能夠看到耗時增長到接近1微妙。

咱們分別對打印源碼文件名，和不打印源碼文件名的標準庫作benchmark對比：

//BenchmarkLog-4                    754929          1672 ns/op           0 B/op           0 allocs/op
func BenchmarkLog(b *testing.B) {
    fp, _ := os.Create("/dev/null")
    log.SetOutput(fp)
    log.SetFlags(0)
    b.ResetTimer()
    for n := 0; n < b.N; n++ {
        log.Printf("a")
    }
}

//BenchmarkLogWith-4                344067          3403 ns/op         216 B/op           2 allocs/op
func BenchmarkLogWith(b *testing.B) {
    fp, _ := os.Create("/dev/null")
    log.SetOutput(fp)
    log.SetFlags(log.Lshortfile)
    b.ResetTimer()
    for n := 0; n < b.N; n++ {
        log.Printf("a")
    }
}

能夠看到耗時增長了一倍。benchmark的源碼：https://github.com/q191201771...

有意思的是，標準庫中可能也以爲獲取源碼文件名的操做太耗時了，因此在調用runtime.Caller前會先釋放鎖，等調用結束後，再把鎖加回來。這麼作鎖的粒度是小了點，可是鎖的操做變多了。我的以爲還不如把runtime.Caller的調用移到頭次加鎖的前面，這樣既減小鎖粒度，又不增長拿鎖的次數。

另外，標準庫中，將獲取日誌時間的time.Now調用放在了加鎖以前，這麼作鎖的粒度是小了，可是極端狀況下，可能先調用time.Now的協程後獲取到鎖，也即日誌中可能出現後面的日誌比前面的日誌時間還要早的狀況。

另外，標準庫中把源碼文件名和行號打印在行首，我我的不太喜歡，由於文件名和行號不是定長的，這將致使業務上的日誌的起始位置不是固定的，看起來很彆扭，我更習慣將文件名和行號打印到行尾。

另外，聊一下c/c++，它們經過__FILE__, __LINE__, __func__,這三個宏來獲取源碼文件名、行號、函數，這些宏會在編譯的時候替換爲所在源碼位置中的文件名等信息。開銷比Go要小不少。

最後，我根據本身平常的使用習慣，也寫了一個日誌庫，供參考。github地址：https://github.com/q191201771...

本文完，做者yoko，尊重勞動人民成果，轉載請註明原文出處： https://pengrl.com/p/20050/
本篇文章由一文多發平臺ArtiPub自動發佈