为什么在 defer 中不能直接使用 time.Since？

问题背景

在 Go 语言开发中，我们经常需要记录函数的执行耗时，特别是在需要性能监控的场景下。一个常见的模式是：

func SomeFunction() {
    start := time.Now()
    defer glog.Infof("function took: %d ms", time.Since(start).Milliseconds())
    // ... 业务逻辑
}

但是当你运行 go vet 时，会收到这样的警告：

call to time.Since is not deferred

这到底是怎么回事？为什么 go vet 会报警？

核心原因：Defer 参数求值时机

要理解这个问题，首先需要明白 Go 中 defer 的执行机制。

1. Defer 的参数是立即求值的

defer fmt.Println(time.Now())  // 输出的是 defer 注册时的时间，而不是函数返回时的时间

当你写 defer glog.Infof("...", time.Since(start)) 时：

• time.Since(start) 在 defer 语句被注册时立即执行
• 计算出的结果作为参数传递给 glog.Infof
• 等到函数返回时，glog.Infof 被调用，但使用的是已经计算好的旧值

2. 你的代码实际上在做什么

func MyFunction() {
    start := time.Now()
    defer glog.Infof("cost: %d ms", time.Since(start).Milliseconds())
    // 这里 time.Since(start) 在 defer 注册时就执行了
    // 此时距离 start 可能只有几微秒
    // 但函数真正返回时可能已经过了几秒
}

这就导致记录的耗时严重不准确！

为什么 go vet 只对 time.Since 报错？

实际上，time.Since 和 time.Now().Sub 在 defer 中的行为是一样的——都会立即求值。

// 这两种写法在 defer 中都会立即求值
defer log.Infof("...", time.Since(start).Milliseconds())     // ❌
defer log.Infof("...", time.Now().Sub(start).Milliseconds()) // ❌ 同样有问题

那为什么 go vet 只对 time.Since 报错？

因为 go vet 内置了针对 time.Since 的特殊检测规则。它发现你在 defer 中直接调用了 time.Since，认为这很可能是一个编程错误，所以给出警告。而 time.Now().Sub() 则绕过了这个特殊检测，但问题本质是一样的。

正确的解决方案

方案一：使用匿名函数（推荐）

func MyFunction() {
    start := time.Now()
    defer func() {
        glog.Infof("function cost: %d ms", time.Since(start).Milliseconds())
    }()
    // ... 业务逻辑
}

这样 time.Since(start) 会在函数返回时执行，获得正确的时间差。

方案二：传递 start 参数

func MyFunction() {
    start := time.Now()
    defer func(t time.Time) {
        glog.Infof("function cost: %d ms", time.Since(t).Milliseconds())
    }(start)
    // ... 业务逻辑
}

方案三：在 defer 中重新计算

func MyFunction() {
    start := time.Now()
    defer glog.Infof("function cost: %d ms", time.Now().Sub(start).Milliseconds())
    // ... 业务逻辑
}

💡 注意

虽然这不会触发 go vet 警告，但问题依然存在！time.Now().Sub(start) 仍然会在 defer 注册时立即求值。

实际案例对比

package main

import (
    "fmt"
    "time"
)

func wrong() {
    start := time.Now()
    defer fmt.Printf("Wrong: %d ms\n", time.Since(start).Milliseconds())
    time.Sleep(2 * time.Second)
    // 输出: Wrong: 0 ms  (因为 time.Since 在 defer 注册时就执行了)
}

func correct() {
    start := time.Now()
    defer func() {
        fmt.Printf("Correct: %d ms\n", time.Since(start).Milliseconds())
    }()
    time.Sleep(2 * time.Second)
    // 输出: Correct: 2000 ms
}

func main() {
    wrong()
    correct()
}

最佳实践

1. 始终使用匿名函数包装 defer 中的复杂计算
2. 不要试图用 time.Now().Sub() 来绕过 go vet 检查
3. 运行 go vet 作为 CI/CD 的一部分

// 推荐模式
func (s *Service) DoSomething() error {
    start := time.Now()
    defer func() {
        glog.Infof("DoSomething cost: %d ms", time.Since(start).Milliseconds())
    }()

    s.mu.Lock()
    defer s.mu.Unlock()

    // ... 业务逻辑
    return nil
}

总结

• time.Since 和 time.Now().Sub 在 defer 中都会立即求值
• go vet 只针对 time.Since 报警，但两种写法都有问题
• 正确的做法是使用匿名函数延迟执行
• 不要为了绕过 go vet 而使用 time.Now().Sub()，这是治标不治本

记住：在 defer 中需要延迟计算的表达式，一律用匿名函数包装！