2018-02-27

golang defer的"坑"

今天同事在计算程序耗时的时候遇到了一个问题：命名一个耗时非常长的函数，计算出来的耗时总是0ms，于是顺藤摸瓜，我们发现了golang中defer关键字的一个需要特别注意的地方，如果你不明白这个特性，下次也可能犯同样的错误，这里记录下这个问题。他的代码是这样的:

package main

import (
	"log"
	"time"
)

func f() {
	var start = time.Now()
	defer log.Printf("use %f seconds", time.Now().Sub(start).Seconds())
	time.Sleep(time.Second * 3)
}
func main() {
	f()
}
// 2018/02/27 22:37:53 use 0.000001 seconds

这里代码中已经sleep了3秒了，但是计算出来的耗时却几乎为0。原因是defer关键字后面接一个方法的调用，程序在执行到defer的时候会创建一个defer栈，方法以及参数都会入栈，这里就需要计算出方法的参数的具体值，将这个值保存在栈中，所以这里的日志虽然没有直接打印出来，但是log.Printf的方法的每个参数都已经计算出来了，也就是说time.Now().Sub(start).Seconds()这行代码其实是已经执行了的。这也就不难解释为什么计算出来的耗时总是接近于0.我写个代码验证一下这个问题。

import (
	"log"
)

func p() string {
	log.Println("hello")
	return "hello"
}
func f(str string) {
}
func main() {
	defer f(p())
	log.Print("world")
}
//2018/02/27 22:48:55 hello
//2018/02/27 22:48:55 world

输出与我们预期的一致。