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自動釋出

Go日誌，列印原始碼檔名和行號造成的效能開銷

相關文章