Measuring execution time in Go

Simple timing in golang

Sometimes you just want to do some quick and dirty timing of a code segment. A simple way to time execution in Golang is to use the time.Now() and time.Since() functions:

func main() {
    start := time.Now()

    r := new(big.Int)
    fmt.Println(r.Binomial(1000, 10))

    elapsed := time.Since(start)
    log.Printf("Binomial took %s", elapsed)
}

You'll need to import the time package to use this. The output is like expected from a timing mechanism:

2013/05/29 23:16:42 Binomial took 179us

Sure, this works for function calls too, but it gets messy quickly. What if we have different return paths, or we want to apply this trick to many pieces in the code? Then you can use the timeTrack trick.

Timing functions in golang

When it comes to timing function calls, there is this neat little trick adapted from Stathat:

func timeTrack(start time.Time, name string) {
    elapsed := time.Since(start)
    log.Printf("%s took %s", name, elapsed)
}

which can be placed near the top of your code, and then used to time any function like this:

func factorial(n *big.Int) (result *big.Int) {
    defer timeTrack(time.Now(), "factorial")
    // ... do some things, maybe even return under some condition
    return n
}

Here's what the output looks like:

2013/05/29 23:16:42 factorial took 82us

You can customize this timeTrack function easily: replace the log call with anything you want, or remove the name parameter if that bothers you.

How does this work?

Go's built-in defer statement defers execution of the specified function until the current function returns. So no matter what route the factorial function takes to return, the defer call will be made right before. Additionally, any parameters given to the timeTrack function will be evaluated the moment the defer call is made, so the time.Now() that gets passed to timeTrack really is the start time of the factorial function you want to time.

Full Source and Playground

You can check out the full code and working example and play around with it on the Go Playground.

Be forewarned though, the Playground always returns timestamps to be 1257894000 (Tue, 10 Nov 2009 23:00:00, the date Go became a public open source project!) so the difference between two timestamps is always 0. They do this so programs behave deterministically and can be cached. You'll have to run it locally to see the real execution times.