美文网首页
Go日志,打印源码文件名和行号造成的性能开销

Go日志,打印源码文件名和行号造成的性能开销

作者: 就想叫yoko | 来源:发表于2020-05-31 14:16 被阅读0次

    日志中打印源码文件名和行号,是非常实用的功能,尤其是开发阶段的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/naza/blob/master/playground/p12/p12_test.go

    有意思的是,标准库中可能也觉得获取源码文件名的操作太耗时了,所以在调用runtime.Caller前会先释放锁,等调用结束后,再把锁加回来。这么做锁的粒度是小了点,但是锁的操作变多了。个人觉得还不如把runtime.Caller的调用移到头次加锁的前面,这样既减少锁粒度,又不增加拿锁的次数。

    另外,标准库中,将获取日志时间的time.Now调用放在了加锁之前,这么做锁的粒度是小了,但是极端情况下,可能先调用time.Now的协程后获取到锁,也即日志中可能出现后面的日志比前面的日志时间还要早的情况。

    另外,标准库中把源码文件名和行号打印在行首,我个人不太喜欢,因为文件名和行号不是定长的,这将导致业务上的日志的起始位置不是固定的,看起来很别扭,我更习惯将文件名和行号打印到行尾。

    另外,聊一下c/c++,它们通过__FILE__, __LINE__, __func__,这三个宏来获取源码文件名、行号、函数,这些宏会在编译的时候替换为所在源码位置中的文件名等信息。开销比Go要小很多。

    最后,我根据自己日常的使用习惯,也写了一个日志库,供参考。github地址:https://github.com/q191201771/naza

    本文完,作者yoko,尊重劳动人民成果,转载请注明原文出处: https://pengrl.com/p/20050/

    本篇文章由一文多发平台ArtiPub自动发布

    相关文章

      网友评论

          本文标题:Go日志,打印源码文件名和行号造成的性能开销

          本文链接:https://www.haomeiwen.com/subject/rznlzhtx.html