Say you want to figure out how long it takes for a function to run. One (bad) way would be to do something like this:

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

        for i := 0; i < 100; i++ {
                fmt.Printf("I can count: %d\n", i)
        }

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

This works, but it will start to get messy if there is more than one way to return from the function:

func x() error {
        start := time.Now()

        for i := 0; i < 100; i++ {
                err := Save(i)
                if err != nil {
                        elapsed := time.Since(start)
                        log.Printf("function x took %s", elapsed)
                        return err
                }
                fmt.Printf("I can count: %d\n", i)
        }

        elapsed := time.Since(start)
        log.Printf("function x took %s", elapsed)
        return nil
}

Fortunately, there is a much better way thanks to go’s built-in defer statement. When you defer a function call, that function will run right before the function returns, no matter where the return happens.

So a slightly better version would be:

func x() error {
        start := time.Now()
        defer func() {
                elapsed := time.Since(start)
                log.Printf("function x took %s", elapsed)
        }()

        for i := 0; i < 100; i++ {
                err := Save(i)
                if err != nil {
                        return err
                }
                fmt.Printf("I can count: %d\n", i)
        }

        return nil
}

No repetitive code, but start isn’t needed anywhere else, so we can do this:

func x() error {
        defer func(start time.Time) {
                elapsed := time.Since(start)
                log.Printf("function x took %s", elapsed)
        }(time.Now())

        for i := 0; i < 100; i++ {
                err := Save(i)
                if err != nil {
                        return err
                }
                fmt.Printf("I can count: %d\n", i)
        }

        return nil
}

This might look like it won’t work. If the deferred function doesn’t execute until immediately before the function returns, perhaps the time.Now() call will happen then too and it won’t be measuring how long it took this function to run. But, don’t worry, it works fine. Any argument to a deferred function is evaluated when the defer executes. Not when the deferred function executes, but when the defer statement executes. So since the defer is the first statement in this function, the time.Now() call will happen when the function starts.

To make it reusable anywhere, just extract it to a stand-alone function:

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

func x() {
        defer timeTrack(time.Now(), "x")
        for i := 0; i < 100; i++ {
                err := Save(i)
                if err != nil {
                        return err
                }
                fmt.Printf("I can count: %d\n", i)
        }

        return nil
}

func y() {
        defer timeTrack(time.Now(), "y")
        for i := 0; i < 100; i++ {
                fmt.Printf("I can count too: %d\n", i)
        }
}

Of course, you can do whatever you want with the elapsed value: log it, save it to a database, or send it to StatHat:

func timeTrack(start time.Time, name string) {
        elapsed := time.Since(start)
        ms := float64(elapsed) / float64(time.Millisecond)
        stathat.PostEZValue(fmt.Sprintf("func %s run time", name), "YOUR_EZKEY", ms)
}