Go
by smallnest

gotips 001: 一行代码测量函数的执行时间

Golang Tips 是翻译的 Phuong Le @func25 陆陆续续的发表的推文，目前已经发表 70+了。我征得Phuong Le 的同意后，会逐步把这些推翻翻译过来，发布到公众号上。

因为是推文，可能原作者的内容比较简单，比如第一个 tip 就一张图片，我会相应的进行扩充，丰富其内容。
后续也会在 github 建立一个项目，大家都可以参与进行翻译。

我们可以通过 defer，实现一行代码来测量某个函数的执行时间：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
func main() {
	defer TrackTime(time.Now()) // 一行代码
	
	time.Sleep(time.Second)
}
func TrackTime(start time.Time) time.Duration {
	elapsed := time.Since(start)
	fmt.Println("elapsed:", elapsed)
	
	return elapsed
}
// elapsed: 1.000704416s

这个 defer 的函数 TraceTime 放在函数内需要测量的起始点，它的参数(start)在此时就会计算出来，在函数返回的时候，它的函数体就会被调用，这是 end 时间也知道了，这样就可以巧妙的计算出来函数执行的时间了。

以下是补充材料

我们还可以使用下面的写法，但是更好更通用些：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
func TrackTime(name string) func() {
	start := time.Now()
	
	return func() {
		fmt.Printf("%s took %v\n", name, time.Since(start))
	}
}
  
func main() {
	defer TrackTime("main")() // 也是一行代码
	time.Sleep(time.Second * 2)
}

这个 defer 的 TraceTime 传入一个辅助信息字符串，方便打日志的能和其它的测量函数所区分。
TraceTime 返回一个类型为 func() 函数匿名函数，这才是 defer 真正调用的函数，它会打印出要测量的函数真正花费的时间。

相比较上面的测量方法，这个函数可以传入辅助字符串，并且不需要自己再调用 time.Now() 获得开始时间。

另外，我还想补充一个测试性能的时候的辅助库：hrtime)。
一般我们会写 Benchmark 的测试代码来测试一段代码逻辑(一般是一个函数，但是也可以是多个函数和语句组成的一段代码逻辑)的性能，但是有的时候，我们可能想写一个程序，更灵活的进行测试，甚至希望得到时间花费的分布情况， hrtime 就是干这个的，就像它的简介中所说，它是Go语言中的高精度计时与基准测试库。

首先我们看一下它的使用方法:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
package main
import (
    "fmt"
    "time"
    "github.com/loov/hrtime"
)
func main() {
    start := hrtime.Now()
    time.Sleep(1000 * time.Nanosecond)
    fmt.Println(hrtime.Since(start))
    const numberOfExperiments = 4096
    bench := hrtime.NewBenchmark(numberOfExperiments)
    for bench.Next() {
        time.Sleep(1000 * time.Nanosecond)
    }
    fmt.Println(bench.Histogram(10))
}

单纯的测量一段代码的执行时间，和常规的我们使用 time package 方法一样，你也可以采用前面介绍的方法，实现一行代码的封装。

同时，类似标准库的 Benchmark 的测量性能的方法，你也可以利用 bench := hrtime.NewBenchmark(numberOfExperiments) 生成一个 bench，进行性能测试，最后通过 bench.Histogram(10) 生成直方图。比如这个例子，我们测试 Sleep 1 微秒时，实际程序会休眠多少微秒。

在我的 Mac mini 的机器上测试，可以看到真正休眠在 5 微秒左右，绝大部分时间落在了 15 微秒以内。