gotimedefer-keyword

Measure elapsed time with a defer statement in Go

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?

Solution

  • 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.