Why can't time.Since be used directly in defer?

Problem background

In Go language development, we often need to record the execution time of functions, especially in scenarios that require performance monitoring. A common pattern is:

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

But when you run go vet When this occurs, you will receive a warning like this:

call to time.Since is not deferred

What exactly is going on? Why go vet Will it call the police?

Core reason: Defer parameter evaluation timing

To understand this issue, you first need to understand in Go defer the execution mechanism.

1. The arguments of defer are evaluated immediately.

defer fmt.Println(time.Now())  // It outputs the time when defer is registered, not the time when the function returns.

When you write defer glog.Infof("...", time.Since(start)) Time:

• time.Since(start) at defer When the statement is registered Execute immediately

• The calculated result is passed as a parameter to glog.Infof

• When the function returns,glog.Infof is called, but uses the old value that has already been calculated

2. What your code is actually doing

func MyFunction() {
    start := time.Now()
    defer glog.Infof("cost: %d ms", time.Since(start).Milliseconds())
    // Here, time.Since(start) is executed when the defer is registered.
    // At this point, it may be only a few microseconds until start.
    // But by the time the function actually returns, several seconds may have already passed.
}

This makes the recorded time consumption seriously inaccurate!

Why go vet Only for time.Since Error?

Actually,time.Since and time.Now().Sub The behavior in defer is the same.——will all be evaluated immediately.

// Both of these forms are evaluated immediately in defer.
defer log.Infof("...", time.Since(start).Milliseconds())     // ❌
defer log.Infof("...", time.Now().Sub(start).Milliseconds()) // ❌ Same problem

Then why go vet only for time.Since Error?

because go vet Built in for time.Since special detection rules. It found that you are defer directly called in time.Since, considering this is likely a programming error, so a warning is given. And time.Now().Sub() then bypasses this special detection, but The essence of the problem is the same..

The correct solution

Option 1: Use anonymous functions (recommended)

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

Like this time.Since(start) will execute when the function returns, obtaining the correct time difference.

Option 2: Pass the start parameter

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

Option 3: Recalculate in defer

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

💡 Note

Although this won't trigger go vet Warning, but The problem still exists.!time.Now().Sub(start) It will still be evaluated immediately when defer is registered.

Actual case comparison

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)
    // Output: Wrong: 0 ms (because time.Since is executed when defer is registered)
}

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

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

Best practices

• Always use anonymous functions to wrap complex computations in defer.

• Don't try to use time.Now().Sub() to bypass go vet Check

• Run go vet As part of CI/CD

// Recommended mode
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()

    // ... business logic
    return nil
}

Summary

• time.Since and time.Now().Sub In defer, they are all evaluated immediately.

• go vet Only targeting time.Since Alarm, but both ways of writing have problems.

• The correct approach is to use an anonymous function for deferred execution.

• Don't do it just to bypass go vet and use time.Now().Sub(), this is treating the symptoms, not the root cause.

Remember: expressions that need to be evaluated lazily in defer should always be wrapped in an anonymous function!