Goログ、ソースファイル名と行番号の印刷によるパフォーマンスオーバーヘッド

ログにソースファイル名と行番号を印刷するのは、非常に実用的な機能であり、特に開発段階のdebugログでは、ログを通じて対応するソースコードの位置を迅速に見つけることができます.
Go標準ライブラリのpackage logは、ソースファイル名と行番号の印刷もサポートしています.開く方法は、次の2つのフラグのいずれかを設定します.

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)
    }
}

1回で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に近い微妙に増えているのが見えます.
ソースファイル名を印刷する標準ライブラリと、ソースファイル名を印刷しない標準ライブラリをそれぞれ比較します.

//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")
    }
}

消費時間が2倍に増えていることがわかります.benchmarkのソース:https://github.com/q191201771...
興味深いことに、標準ライブラリではソースファイル名を取得する操作に時間がかかりすぎると感じているかもしれないので、runtime.Callerを呼び出す前にロックを解放し、呼び出しが終わったらロックを戻します.このようにロックの粒度は少し小さいですが、ロックの操作が多くなりました.個人的にはruntime.Callerの呼び出しを最初のロックの前に移動するほうが、ロックの粒度を減らし、ロックを取る回数を増やさないと思います.
また、標準ライブラリでは、取得ログ時間のtime.Now呼び出しをロックする前に置くと、ロックの粒度は小さくなりますが、極端には、time.Nowのスレッドを呼び出してロックを取得する可能性があります.つまり、ログに前のログ時間よりも後のログが発生する可能性があります.
また、標準ライブラリではソースファイル名と行番号を行頭に印刷していますが、個人的にはあまり好きではありません.ファイル名と行番号は長く設定されていないため、ビジネス上のログの開始位置が固定されていないため、違和感があり、ファイル名と行番号を行末に印刷するのに慣れています.
また、c/c++についてお話しします.__FILE__, __LINE__, __func__,という3つのマクロによってソースファイル名、行番号、関数が取得され、これらのマクロはコンパイル時にソースコードの位置にあるファイル名などの情報に置き換えられます.オーバーヘッドはGoよりずっと小さいです.
最後に、私は自分の日常の使用習慣に基づいて、参考のためにログライブラリも書きました.githubアドレス:https://github.com/q191201771...
本文は終わって、作者のyoko、労働人民の成果を尊重して、転載して原文の出所を明記してください:https://pengrl.com/p/20050/本の文章は1文の多発プラットフォームのArtiPubから自動的に発表します