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

by

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)
}

Leave a Comment