Measure elapsed time with a defer statement in Go

Question

I thought of using the defer statement to measure the elapsed time of a program in Go:

func main() {
    start := time.Now()
    defer fmt.Println(fmt.Sprintf("The process took %s", time.Now().Sub(start)))
    ...
}

I thought this would produce the correct result but it didn't:

[09:36:55]pc@work:~/test$ go run ./main.go
Processed 209806/209806 TUF files
All records are inserted in the database.
Verifying records are inserted correctly...
Verified 209806/209806 TUF files
All records have been inserted and verified successfully.
The process took 600ns
[14:24:06]pc@work:~/test$

Even though the process took 5 hours, which is visible from the timestamps on the left, the deferred fmt.Println() statement showed 600 nanoseconds. What am I doing wrong?

Answer 1

Defered function arguments are evaluated immediately. You can wrap their evaluation into an anonymous function to delay their evaluation until the defer actually gets triggered:

defer func() {
    fmt.Println(fmt.Sprintf("The process took %s", time.Now().Sub(start)))
}()

Read more about the defer statement in A Tour of Go and the language specification.

Answer 2

The arguments to the deferred function are evaluated right away, meaning the time.Now().Sub(start) part is computed right after the start.

If you want to time the function, say:

defer func() {
    time.Now().Sub(start) // ...
}()

Alternatively, I have written a package for it: https://github.com/gonutz/tic so you can say:

func main() {
    defer tic.Toc()()
}

and note the two ()() which are there for the exact same reason, the first function call starts the timing and returns a function to be deferred which stops the timing.