【译文】原文地址
对函数进行分析是很重要的。了解函数的执行时间可以发现代码中隐藏的瓶颈，在生产环境中发布特性之前提供清晰的延时估算，能够为查找代码中低效算法提供线索。然而，测试函数的执行时间不是函数的核心业务逻辑，因此测量函数执行时间的代码不应该对业务代码有侵入。
低级实现方式
假设我们有一个函数做一些耗时的事。比如，每间隔100ms打印1到5整数。代码如下：
func expensivePrint() {
for i := 1; i <= 5; i++ {
fmt.Printf("Current number is %d \n", i)
time.Sleep(100 * time.Millisecond)
}
}
然后main函数调用上面的函数，完成执行。
func main() {
expensivePrint()
fmt.Println("Finished executing main")
}
执行结果：
Current number is 1
Current number is 2
Current number is 3
Current number is 4
Current number is 5
Finished executing main
现在，出于监控目的，我们想对expensivePrint函数执行时间进行测量。一种简单的方法是在函数开始处记录开始时间，并在函数结束时检查与当前时间的差异。
func expensivePrint() {
start := time.Now()
for i := 1; i <= 5; i++ {
fmt.Printf("Current number is %d \n", i)
time.Sleep(100 * time.Millisecond)
}
fmt.Printf("Time taken by expensivePrint function is %v \n", time.Since(start))
}
执行main函数结果为：
Current number is 1
Current number is 2
Current number is 3
Current number is 4
Current number is 5
Time taken by expensivePrint function is 511.532405ms
Finished executing main
正如我们所看到的，这与预期的一样有效。然而，这种方法存在一些问题。
- 问题一：代码的侵入性
这种方法的一个问题是，代码本质上是非常具有侵入性的。您必须记住在每个函数开始时计算开始时间，并在每个函数结束时测量时间差。 - 问题二：不能统一日志记录规则
这种方法的另一个问题是，即使团队中的开发人员都记得添加测量时间的代码，但在函数最后一行记录时间差是的记录格式不能保证每个人都统一，这对后期查找对应的日志造成困难。例如，一些开发人员可能用不同的方式写日志：
fmt.Printf("A different sentence to measure execution of %v \n", time.Since(start))
这使得您越来越难以发现代码中的问题。您需要一种方法，使所有的时间日志记录语句看起来相同。
- 问题三：不支持修改
如果更新写入日志的方式，需要对记录执行时间的每个函数进行代码更改。例如:如果您已经从使用fmt改为使用log，那么所有使用上述方式的函数都需要进行代码更新。
高级实现方式
为了解决以上所有问题，让我们看看高级的实现。首先，为了解决后两个问题，我们有必要将时间测量代码放到一个单独的函数中，并在需要的地方调用该函数。为了做到这一点，我们创建一个函数，可接收函数执行开始时间参数和被测量函数名称，并打印日志：
func printTimeMeasurement(funcName string, start time.Time) {
fmt.Printf("Time taken by %s function is %v \n", funcName, time.Since(start))
}
调用这个函数替换我们对fmt包的直接调用，使我们的代码具有同质性和可维护性。但是，它仍然是侵入性的，因为它需要在函数开始时记录开始时间。我们将使用Golang提供的defer语句来解决这个问题。根据Golang官方博客：
defer语句将函数调用放到一个栈内。压入栈的函数将在所在函数返回之执行。
我们将printTimeMeasurement函数改为，将实际打印执行时间的日志功能作为函数返回。
func printTimeMeasurement(funcName string, start time.Time) func() {
return func() {
fmt.Printf("Time taken by %s function is %v \n", funcName, time.Since(start))
}
}
现在，让我们编写一个函数measureTime来跟踪开始时间，并返回一个调用：
func measureTime(funcName string) func() {
start := time.Now()
return printTimeMeasurement(funcName, start)
}
接下来，将原先的expensivePrint函数，直接使用defer语句调用上面的 measureTime，传入函数名即可：
func expensivePrint() {
defer measureTime("expensivePrint")()
for i := 1; i <= 5; i++ {
fmt.Printf("Current number is %d \n", i)
time.Sleep(100 * time.Millisecond)
}
}
输出为：
Current number is 1
Current number is 2
Current number is 3
Current number is 4
Current number is 5
Time taken by expensivePrint function is 514.630708ms
Finished executing main
简化代码
measureTime中的printTimeMeasurement函数可以使用匿名函数代替，简化为如下：
func measureTime(funcName string) func() {
start := time.Now()
return func() {
fmt.Printf("Time taken by %s function is %v \n", funcName, time.Since(start))
}
}
匿名函数可以使用start和funcName变量，因此不需要这些参数作为函数参数。下面是完整代码：
package main
import (
"fmt"
"time"
)
func measureTime(funcName string) func() {
start := time.Now()
return func() {
fmt.Printf("Time taken by %s function is %v \n", funcName, time.Since(start))
}
}
func expensivePrint() {
defer measureTime("expensivePrint")()
for i := 1; i <= 5; i++ {
fmt.Printf("Current number is %d \n", i)
time.Sleep(100 * time.Millisecond)
}
}
func main() {
expensivePrint()
}
代码非常简单，现在只需向代码库中的所有函数添加一个defer调用，就可以测量它们的运行时间。对度量时间函数所做的任何更改，都会在整个代码库中反映出来，从而确保代码的可维护性。
使用惯用的Golang模式，如延迟和匿名函数，可以帮助我们编写简单、高效的代码。这是一个例子。
