why defer statement works differently when annoymouse function returned

Question

here i declare a function which defer trace1

func TestDeferFunc(t *testing.T) {
    fmt.Println("start", time.Now())
    defer trace1()
    time.Sleep(3 * time.Second)
}

func trace1() {
    startTime := time.Now()
    fmt.Println("end time: ", startTime)
    fmt.Println("execute time: ", time.Since(startTime))
}

after run go test -run=^TestDeferFunc$,below is what i got

start 2019-11-26 12:50:59.59489797 +0800 CST m=+0.000202866
end time:  2019-11-26 12:51:02.595090951 +0800 CST m=+3.000395880
execute time:  49.065µs

howerver, when i defer another annoymouse function, things changed

func TestDeferFunc(t *testing.T) {
    fmt.Println("start", time.Now())
    defer trace2()()
    time.Sleep(3 * time.Second)
}

func trace2() func() {
    startTime := time.Now()
    fmt.Println("end time: ", startTime)
    fmt.Println("execute time: ", time.Since(startTime))
    return func() {
        fmt.Println("zzz")
    }
}

below is the go test result

start 2019-11-26 12:52:58.318472958 +0800 CST m=+0.000197852
end time:  2019-11-26 12:52:58.318554368 +0800 CST m=+0.000279262
execute time:  4.853µs
zzz

could someone help me out! thanks

Answer 1

This is because defer statement only defers the evaluated function call - and the function call is evaluated at the time defer execuated. As per doc:

Each time a "defer" statement executes, the function value and parameters to the call are evaluated as usual and saved anew but the actual function is not invoked. Instead, deferred functions are invoked immediately before the surrounding function returns, in the reverse order they were deferred. That is, if the surrounding function returns through an explicit return statement, deferred functions are executed after any result parameters are set by that return statement but before the function returns to its caller. If a deferred function value evaluates to nil, execution panics when the function is invoked, not when the "defer" statement is executed.

Your code defer trace2()() essentially is equlavent of f := trace2(); defer f(). So trace2 gets evaluated (and thus called) immediately.

So to achieve what you might want (tracing time), you may use defer trace3()() with trace3() like this:

func trace3() func() {
    startTime := time.Now()

    return func() {
        fmt.Println("end time: ", time.Now())
        fmt.Println("execute time: ", time.Since(startTime))
    }
}