Today, I wanted to add some timings to a function call in Go.

I wanted something very simple, so I opted for:

package main
 
import (
    "fmt"
    "time"
)
 
func main() {
 
    start := time.Now()
    defer fmt.Println("ELAPSED:", time.Since(start))
 
    time.Sleep(2 * time.Second)
 
}

When running this, I was a bit surprised I got the following result:

$ go run defertester1.go
ELAPSED: 186ns

I was expecting to see an elapsed time of at least 2 seconds.

The caveat here is that as soon as the defer statement is called, it's already evaluating the result of fmt.Println("ELAPSED:", time.Since(start)).

After a search on StackOverflow, here's a nice description of why the result is like this:

The deferred call's arguments are evaluated immediately, but the function call is not executed until the surrounding function returns. For example, defer outcall(incall()), the incall() is evaluated immediately, while the outcall() is not executed until the surrounding function returns.

To get the correct result, you need to wrap this in a function call so that it only gets evaluated when the defer statement is executed.

package main
 
import (
    "fmt"
    "time"
)
 
func main() {
 
    start := time.Now()
    defer func() {
        fmt.Println("ELAPSED:", time.Since(start))
    }()
 
    time.Sleep(2 * time.Second)
 
}

When we execute this, we now get the expected result:

$ go run defertester2.go
ELAPSED: 2.004822262s