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/


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

查看所有标签

猜你喜欢:

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

代码整洁之道:程序员的职业素养

代码整洁之道:程序员的职业素养

罗伯特·C.马丁 (Robert C.Martin) / 余晟、章显洲 / 人民邮电出版社 / 2016-9-1 / 49.00元

1. 汇聚编程大师40余年编程生涯的心得体会 2. 阐释软件工艺中的原理、技术、工具和实践 3. 助力专业软件开发人员具备令人敬佩的职业素养 成功的程序员在以往的工作和生活中都曾经历过大大小小的不确定性,承受过永无休止的压力。他们之所以能够成功,是因为拥有一个共同点,都深切关注创建软件所需的各项实践。他们将软件开发视为一种需要精雕细琢加以修炼的技艺,他们以专业人士的标准要求自己,......一起来看看 《代码整洁之道:程序员的职业素养》 这本书的介绍吧!

JS 压缩/解压工具
JS 压缩/解压工具

在线压缩/解压 JS 代码

随机密码生成器
随机密码生成器

多种字符组合密码

HEX HSV 转换工具
HEX HSV 转换工具

HEX HSV 互换工具