Go语言使用defer统计程序执行耗时结果异常问题排查

该写法不符合Go语言defer的核心执行规则：defer语句注册时，所有传入被调用函数的参数会立即完成求值，不会等到函数返回前、defer逻辑实际执行时才计算。

你的代码实际执行顺序如下：

• 执行start := time.Now()记录启动时间
• 立刻执行作为fmt.Println参数的fmt.Sprintf(...)，计算当前时间和start的差值——此时距离start赋值仅过去600ns，直接生成了The process took 600ns的固定字符串
• 注册defer逻辑，约定main函数退出前调用fmt.Println(刚才提前算好的字符串)
• 执行业务逻辑（文件处理、数据库插入、数据校验），总共耗时近5小时
• main函数准备退出，执行defer逻辑，直接打印第二步就生成好的固定字符串，完全没有统计到后续业务逻辑的执行时长，因此结果和实际耗时偏差极大。

写法1：匿名函数包裹 #

把耗时计算逻辑放到匿名函数内部，保证计算逻辑在defer实际执行时才运行：

func main() {
    start := time.Now()
    defer func() {
        fmt.Printf("The process took %s\n", time.Since(start))
    }()
    // 原有业务逻辑
}

写法2：封装耗时统计辅助函数 #

利用defer的参数求值规则，把开始时间作为参数传入，统计逻辑放在函数体中：

func calculateCost(start time.Time) {
    fmt.Printf("The process took %s\n", time.Since(start))
}

func main() {
    defer calculateCost(time.Now())
    // 原有业务逻辑
}

内容的提问来源于stack exchange，提问作者Stefan Zhelyazkov