How do you time a function in Go and return its runtime in milliseconds?

Question

How do you time a function in Go and return its runtime in milliseconds?

Answer 1

Go's defer makes this trivial.

In Go 1.x, define the following functions:

func trace(s string) (string, time.Time) {
    log.Println("START:", s)
    return s, time.Now()
}

func un(s string, startTime time.Time) {
    endTime := time.Now()
    log.Println("  END:", s, "ElapsedTime in seconds:", endTime.Sub(startTime))
}

After that, you get Squeaky Clean one line elapsed time log messages:

func someFunction() {
    defer un(trace("SOME_ARBITRARY_STRING_SO_YOU_CAN_KEEP_TRACK"))

    //do a bunch of stuff here...
}

The clever magic is that the trace() is called at the beginning of the function, but the un() is deferred to the end. It's not atomic-clock accurate, due to the log statements, but if you need more accuracy, this kind of pattern is one of Go's marshmallowy good strengths.

EDIT:

This answer originally used legacy time package API. Reproduced here for historical value only:

For use w/ Go versions prior to 12-01-2011 weekly:

func trace(s string) (string, int64) {
    log.Println("START:", s)
    return s, time.Nanoseconds()
}

func un(s string, startTime int64) {
    endTime := time.Nanoseconds()
    log.Println("  END:", s, "ElapsedTime in seconds:", float32(endTime-startTime)/1E9)
}

Answer 2

Use the Go testing package to benchmark the function. For example,

package main

import (
    "fmt"
    "testing"
)

// the function to be benchmarked
func Function(n int) int64 {
    n64 := int64(n)
    return n64 * n64
}

func BenchmarkFunction(b *testing.B) {
    n := 42
    for i := 0; i < b.N; i++ {
        _ = Function(n)
    }
}

func main() {
    br := testing.Benchmark(BenchmarkFunction)
    fmt.Println(br)
}

Output:

500000000            4.22 ns/op

You can also use the Go gotest command to run benchmarks.

Answer 3

Another easy way can be:

import (
    "fmt"
    "time"
)

start := time.Now()
// some computation
elapsed := time.Since(start)
fmt.Println(elapsed)

which will output something like 359.684612ms

Answer 4

Perhaps you can also use a Duration (elapsed) for this...looks a little bit nicer.

func trace(s string) (string, time.Time) {
    log.Printf("trace start: %s\n", s)
    return s, time.Now()
}

func un(s string, startTime time.Time) {
    elapsed := time.Since(startTime)
    log.Printf("trace end: %s, elapsed %f secs\n", s, elapsed.Seconds())
}

Answer 5

There are several options for timestamping and timers in the time package. See the documentation here: http://golang.org/pkg/time/