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

栏目: IT技术 · 发布时间: 4年前

内容简介:日志中打印源码文件名和行号,是非常实用的功能,尤其是开发阶段的debug日志,可以快速通过日志找到对应的源码位置。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/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/


以上就是本文的全部内容,希望对大家的学习有所帮助,也希望大家多多支持 码农网

查看所有标签

猜你喜欢:

本站部分资源来源于网络,本站转载出于传递更多信息之目的,版权归原作者或者来源机构所有,如转载稿涉及版权问题,请联系我们

Visual Thinking

Visual Thinking

Colin Ware / Morgan Kaufmann / 2008-4-18 / USD 49.95

Increasingly, designers need to present information in ways that aid their audiences thinking process. Fortunately, results from the relatively new science of human visual perception provide valuable ......一起来看看 《Visual Thinking》 这本书的介绍吧!

在线进制转换器
在线进制转换器

各进制数互转换器

MD5 加密
MD5 加密

MD5 加密工具

Markdown 在线编辑器
Markdown 在线编辑器

Markdown 在线编辑器