Go零消耗debug log技巧

tL;DR, 本文末尾提供零消耗的日志代码,最高性能提升60000%。

看到题目,有人肯定会问,官方的log模块不好么?
Debug Log一般很长,在生产环境还输出的话,也很难找。
再者,log的消耗是比较大的,特别是需要打印行号时。

https://golang.org/src/log/log.go#L158

if l.flag&(Lshortfile|Llongfile) != 0 {
// Release lock while getting caller info - it's expensive.
l.mu.Unlock()
var ok bool
_, file, line, ok = runtime.Caller(calldepth)
if !ok {
file = "???"
line = 0
}
l.mu.Lock()
}

因为需要调用runtime.Caller,这样性能就有较多的损耗。
简单的benchmark,可以发现慢50%。

func BenchmarkWithLine(b *testing.B) {
logger := log.New(ioutil.Discard, "", log.Llongfile|log.LstdFlags)
tf := strings.Repeat("abcde", 1000)
b.ResetTimer()
for i := 0; i < b.N; i++ {
logger.Print(tf)
}
}
// BenchmarkWithLine-4 500000 2806 ns/op
// BenchmarkWithoutLine-4 1000000 1754 ns/op

虽然,log的性能不差,仅需要1us就能进行一次,但如果在代码中有大量的debug日志,这个损耗累积起来,那也是相当惊人的了。

那么,在生产环境,能不能不执行log语句呢?
可以的,例如

const Dev = false
func BenchmarkConst(b *testing.B) {
logger := log.New(ioutil.Discard, "", log.LstdFlags)
tf := strings.Repeat("abcde", 1000)
b.ResetTimer()
for i := 0; i < b.N; i++ {
if Dev {
logger.Print(tf)
}
}
}
// BenchmarkConst-4 2000000000 0.29 ns/op

go tool objdump查看生成的二进制文件

 log_test.go:36 0x4efc32 48890424 MOVQ AX, 0(SP)
log_test.go:36 0x4efc36 e815d4fbff CALL testing.(*B).ResetTimer(SB)
log_test.go:36 0x4efc3b 488b842480000000 MOVQ 0x80(SP), AX
log_test.go:36 0x4efc43 31c9 XORL CX, CX
log_test.go:38 0x4efc45 eb03 JMP 0x4efc4a
log_test.go:38 0x4efc47 48ffc1 INCQ CX
log_test.go:38 0x4efc4a 488b90f0000000 MOVQ 0xf0(AX), DX
log_test.go:38 0x4efc51 4839d1 CMPQ DX, CX
log_test.go:38 0x4efc54 7cf1 JL 0x4efc47
log_test.go:43 0x4efc56 488b6c2470 MOVQ 0x70(SP), BP
log_test.go:43 0x4efc5b 4883c478 ADDQ $0x78, SP
log_test.go:43 0x4efc5f c3 RET

可以看出,ResetTimer之后,仅仅是跑了个空的for循环,这是因为编译器发现if语句永远不成立,所以不编译这一段了(如果Dev是var值,那么还是会对比一下,而不是没有语句生成),不过这个方法需要每次debug时都要改代码。不想改代码可以用go build -ldflags -X方法, 但这个仅仅支持字符串,特别麻烦。

所以有没有更好的解决方案呢?有的,使用build tags
下面是例子,一共三个文件:

log.go

package main
func main() {
Debug("it's expensive")
if Dev {
fmt.Println("we are in develop mode")
}
}

log_debug.go

//+build debug
package main
import (
"fmt"
)
const Dev = true
func Debug(a ...interface{}) {
fmt.Println(a...)
}

log_release.go

//+build !debug
package main
const Dev = false
func Debug(a ...interface{}) {}

debug和release最大的差别就在文件头的//+build !debug, 意思是告诉编译器,如果有debug这个tags,那么编译的时候就略过这个文件。
比如你运行go build -tags "debug" && ./main就会输出,不设定的话,就什么都不输出。

再用go tool objdump 查看生成的可执行文件,跟之前的if Dev效果相同,压根不生成语句。这样就不用每次都改代码了来debug了,是不是很赞啊?

对于Debug函数,由于Go的函数是first class,所以Call function不可避免,不过性能损失基本上为零了。

package main
import "testing"
var a = strings.Repeat("abcde", 1024)
func BenchmarkDebug(b *testing.B) {
for i := 0; i < b.N; i++ {
Debug(a)
}
}
go test -bench=.
BenchmarkDebug-4 500000000 3.27 ns/op
go test -bench=. -tags debug
BenchmarkDebug-4 10000000 146 ns/op

总结一下,如果极度要求性能,尽量使用if Dev这种判断模式,如果要求不高,可以使用Debug函数的方法。

发表回复

您的邮箱地址不会被公开。 必填项已用 * 标注

此站点使用Akismet来减少垃圾评论。了解我们如何处理您的评论数据