zhuo/blog

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函数的方法。