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自动发布