60

I'm looking for the best way to calculate execution time in go.

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

    time.Sleep(time.Second * 2)

    //something doing here

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

The code above works fine.

But when I use templates, I have to write it again for each template function.

Is there an efficient way of calculating execution time, including with templates?

John Smith
  • 7,243
  • 6
  • 49
  • 61
Özgür Yalçın
  • 1,872
  • 3
  • 16
  • 26
  • Possible duplicate of [Order of the code and performance](https://stackoverflow.com/questions/41608578/order-of-the-code-and-performance/41608707#41608707). – icza Aug 19 '17 at 07:00
  • Golang's testing package supports https://golang.org/pkg/testing/#hdr-Benchmarks that can help in better examining code.. – Muzafar Ali Mar 26 '21 at 13:43

5 Answers5

128

If you are timing an entire function, then you can use defer to eliminate some of the repetitive code.

// timer returns a function that prints the name argument and 
// the elapsed time between the call to timer and the call to
// the returned function. The returned function is intended to
// be used in a defer statement:
//
//   defer timer("sum")()
func timer(name string) func() {
    start := time.Now()
    return func() {
        fmt.Printf("%s took %v\n", name, time.Since(start))
    }
}

func main() {
    defer timer("main")()  // <-- The trailing () is the deferred call
    time.Sleep(time.Second * 2)
}   // prints: main took 2s

Run the example on the playground.

The specification says this about deferred calls:

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. Instead, deferred functions are invoked immediately before the surrounding function returns,

The function value timer("main") is evaluated at the defer statement. The timer function records the current time and returns an anonymous function. The returned anonymous function is invoked immediately before the surrounding function returns. The anonymous function computes and prints the elapsed time.


Use runtime.Callers and runtime.CallersFrames to automatically get the name of the calling function.

// callerName returns the name of the function skip frames up the call stack.
func callerName(skip int) string {
    const unknown = "unknown"
    pcs := make([]uintptr, 1)
    n := runtime.Callers(skip+2, pcs)
    if n < 1 {
        return unknown
    }
    frame, _ := runtime.CallersFrames(pcs).Next()
    if frame.Function == "" {
        return unknown
    }
    return frame.Function
}

// timer returns a function that prints the name of the calling
// function and the elapsed time between the call to timer and
// the call to the returned function. The returned function is
// intended to be used in a defer statement:
//
//   defer timer()()
func timer() func() {
    name := callerName(1)
    start := time.Now()
    return func() {
        fmt.Printf("%s took %v\n", name, time.Since(start))
    }
}

func main() {
    defer timer()()
    time.Sleep(time.Second * 2)
}   // prints: main.main took 2s

Note that there is a runtime cost for getting the function name compared to using a string literal as in the first part of this answer. To avoid measuring the cost of getting the function name, timer gets the name before recording the start time.

Run the example on the playground.

Charlie Tumahai
  • 113,709
  • 12
  • 249
  • 242
  • 1
    The deferred call's *arguments are evaluated immediately*, but the function call is not executed until the surrounding function returns. For example, `defer outcall(incall())`, the `incall()` is evaluated immediately, while the `outcall()` is not executed until the surrounding function returns. – axiqia Nov 28 '20 at 06:34
27

The solution provided by Cerise Limón is perfect.


In addition, if you don't want to pass function name explicitly, you could accomplish it like this:

func SomeFunction(list *[]string) {
    defer TimeTrack(time.Now())
    // Do whatever you want.
}

func TimeTrack(start time.Time) {
    elapsed := time.Since(start)

    // Skip this function, and fetch the PC and file for its parent.
    pc, _, _, _ := runtime.Caller(1)

    // Retrieve a function object this functions parent.
    funcObj := runtime.FuncForPC(pc)

    // Regex to extract just the function name (and not the module path).
    runtimeFunc := regexp.MustCompile(`^.*\.(.*)$`)
    name := runtimeFunc.ReplaceAllString(funcObj.Name(), "$1")

    log.Println(fmt.Sprintf("%s took %s", name, elapsed))
}

As a result, you would get:

SomeFunction took 15.483µs


For more information, Refer this article: Go Function Tracing

Share the knowledge. :)

serenesat
  • 4,611
  • 10
  • 37
  • 53
Mohsin Aljiwala
  • 2,457
  • 2
  • 23
  • 30
5

Use init function

package main

import (
    "fmt"
    "time"
)

var start time.Time

func init() {
    start = time.Now()
}

func getChars(s string) {
    for _, c := range s {
        fmt.Printf("%c at time %v\n", c, time.Since(start))
        time.Sleep(10 * time.Millisecond)
    }
}

func main() {
    fmt.Println("main execution started at time", time.Since(start))

    getChars("Hello")

    fmt.Println("\nmain execution stopped at time", time.Since(start))
}
Uday Hiwarale
  • 4,028
  • 6
  • 45
  • 48
2

Efficient way to calculate execution time in golang

You can easily get the execution time on your console using a defer function

defer functions execute even if the code get an error so you always get the execution time.

time package is used to get the time difference.

func main() {
    now := time.Now()
    defer func() {
        fmt.Println(time.Now().Sub(now))
    }()
        
    // Here you can do whatever you want
}

Or you can use this code

func main() {
        now := time.Now()
        defer func() {
            fmt.Println(time.Since(now))
        }()
            
        // Here you can do whatever you want
    }

check the code in Playground for more. I added some functionality to recover from an error at the same time print the execution time, even if in the case of a panic error.

Community
  • 1
  • 1
ASHWIN RAJEEV
  • 2,525
  • 1
  • 18
  • 24
  • Deferring after the fact (i.e. after your code you want to time) right before the end of the enclosing function is not really useful, as then you can just as well execute the second timing and printing directly without `defer` and have exactly the same functionality. `defer` exists to schedule some call before the code in question (to be executed thereafter) and to be called regardless of panics or early bail-outs occurring during the code in question. – blubberdiblub Oct 23 '18 at 14:55
  • based on the question defer is useful. It will work even if there is a panic. – ASHWIN RAJEEV Oct 24 '18 at 07:22
  • I did not dispute that `defer` is useful for timing in general (the other answers show a good way to use it). Just the way it's used in **this** answer is not very productive. In particular placing `defer` at the end of the function makes no sense. – blubberdiblub Oct 24 '18 at 12:56
  • @blubberdiblub yeah but defer can placed in any position of the code you want. It will be added to defer stack and will execute whatever the position of the defer function. So I think it is more useful because we can code lazy... – ASHWIN RAJEEV Oct 25 '18 at 04:44
  • `defer` will put stuff onto the `defer` stack at the point it occurs in the code, not any sooner. Try putting a `panic()` (or some function that causes a panic) at the position of your comment and observe that your deferred time printing will **not** happen, because it hadn't been deferred before the panic. You code is effectively no different from the same code without `defer`. – blubberdiblub Oct 25 '18 at 05:24
  • @blubberdiblub yes, In case of a panic you are right – ASHWIN RAJEEV Oct 25 '18 at 05:40
  • @blubberdiblub now check the code it will work even if a panic occur – ASHWIN RAJEEV Oct 25 '18 at 06:04
  • 4
    This answer is no different from the [accepted one](https://stackoverflow.com/a/45766707/125816), which was posted two years ago. What's the point? – Sergio Tulentsev Dec 25 '18 at 19:29
0

Use this as a side reference for an average computation time in Golang (for 10,100,1000 elements accordingly).

  • Accessing an element within an array (1/1/1 sec)
  • Binary/dictionary search (1/2/3 sec)
  • Simple loop/linear search (10/100/1,000 sec)
  • Quick Sort/Merge Sort/Heap Sort/Tim Sort (10/200/3,000 sec)
  • Bubble Sort/Insertion Sort/Selection Sort (100/10,000/1,000,000 sec)
monkrus
  • 1,470
  • 24
  • 23