Golang: Measuring execution time using a deferred function

Simple timing in Golang

A simple way to measure execution time in Golang is to use the time.Now() and time.Since() functions:

func main() {
 start := time.Now()
 time.Sleep(time.Second * 3)
 elapsed := time.Since(start)
 fmt.Printf("Time took %s", elapsed)
}

A Timing function using a deferred function

Here is an example program using a deferred function MeasureTime() to measure execution time:

import (
 "fmt"
 "time"
)
func main() {
 defer MeasureTime("Task One")()
 time.Sleep(time.Second * 3)
 fmt.Println("End")
}
func MeasureTime(process string) func() {
 fmt.Printf("Start %s\n", process)
 start := time.Now()
 return func() {
  fmt.Printf("Time taken by %s is %v\n", process, time.Since(start))
 }
}

Here’s what the output looks like:

Start Task One
End
Time taken by Task One is 3.001237375s

How does this work?

A defer statement defers the execution of the specified until the surrounding function returns.

However, why does it output “Start Task One” first?

The Golang specification says:

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.

func MeasureTime(process string) func() {
 fmt.Printf("Start %s\n", process)
 start := time.Now()
 return func() {
  fmt.Printf("Time taken by %s is %v\n", process, time.Since(start))
 }
}

In the above code, the MeasureTime function returns a function type. Since defer statement needs to evaluate the statement, it will actually execute the MeasureTime function to get the return function. So the code prints out “Start” first.

If a deferred function does not return a function type, then the function body will not be executed until enclosing function returns.