Measure Execution Time

In Go, the simplest way to measure execution time is using the combination of time.Now() and time.Since(). time.Now() records the current time and time.Since() calculates the total time since a specific time.

For measure execution time of a block of code, we just need to do:

t := time.Now()
// Do something
d := time.Since(t)

If we want to measure the execution time of the whole function, the simplest way is to wrap it with a defer:

func doSomething() {
	t := time.Now()
	defer func() {
		d := time.Since(t)
		fmt.Printf("Execution time: %v\n", d)
	}()
	// Do something
}

The above block of code is even better if we break the time measurement logic into a utilities function so that it can be reused across our code base:

func measureTime(context string, t time.Time) {
	d := time.Since(t)
	fmt.Printf("Execution time of %s: %v\n", context, d)
}

func doSomething() {
	defer measureTime("doSomething",time.Now())
	// Do something
}

Multiple Steps

In reality, our function or block of code may have multiple steps inside and we may want to measure their performance. The code can be run consecutively or concurrently. But let consider the below function which has multiple execution steps run consecutively first:

func doSomething() {
	doStep1()
	doStep2()
	doStep3()
}

The execution flow would looks like this:

Apply the same principle as our very first example, the time measurement code would look like this:

func doSomething() {
	t := time.Now()
	defer measureTime("doSomething", t)

	doStep1()
	measureTime("doStep1", t)

	t = time.Now()
	doStep2()
	measureTime("doStep2", t)

	t = time.Now()
	doStep3()
	measureTime("doStep3", t)
}

Concurrency

What if our code uses goroutine? Consider the below function where doStep2 runs inside a goroutine:

func doSomething() {
	doStep1()
	go func() {
		doStep2()
	}()
	doStep3()
}

We can see that after doStep1 , doStep2 and doStep3 will run concurrently. The execution flow would look like:

Base on the execution flow, doStep2 and doStep3 start at the same time (almost). Hence we can do this:

func doSomething() {
	t := time.Now()
	defer measureTime("doSomething", t)

	doStep1()
	measureTime("doStep1", t)

	t = time.Now()
	go func() {
		doStep2()
		measureTime("doStep2", t)
	}()

	doStep3()
	measureTime("doStep3", t)
}

Production Recommendation

The measureTime utilities function is cool but still has some inconvenient when using in production. We might not only want to log the information but also want to save it into database or send it to some monitoring services. Hence we need a better helper utilities to serve those purposes. Luckily, building a helper in this case is very easy.

Let call a function or a block of code as an execution context, each execution context may have one or multiple steps - which we will call as a span. The execution context would look like this:

Base on the above execution flow, we can model information of a execution context as below:

type Record struct {
    // Context is name of the context.
	Context  string                   `json:"context"`
    // Duration hold execution time of the whole context.
	Duration time.Duration            `json:"duration"`
    // Spans hold the execution time of each span in the context.
	Spans    map[string]time.Duration `json:"spans"`
    // Meta hold metadata of the context for tracing purpose.
	Meta     map[string]interface{}   `json:"meta"`
}

Let call our helper as TimeRecorder. The TimeRecorder would need to serve for both consecutive or concurrent execution contextes. Hence it should look like:

type TimeRecorder interface {
	// Done records the execution time of the given span since the last time Done was called.
	// Done updates the internal clock of the recorder.
	Done(span string)

	// Last return the last recorded time of the internal clock of the recorder.
	// Last is normally used with DoneSince.
	Last() time.Time
	
	// DoneSince records the execution time of the given span since the given time.
	// Note that DoneSince doesn't update the internal clock of the recorder.
	// Normally it is used in case there is a span run concurrently with the others.
	DoneSince(span string, t time.Time)

	// Info return time execution info of the context and detail
	// of the recorded spans at the moment.
	Info() Record
}

A simple implementation of the TimeRecorder can be found in this repo.

By using the library above, our code in case of consecutive run would look much simpler:

func doSomething() {
	r := timeutil.NewRecorder("doSomething")
	defer func() { fmt.Println(r.Info()) }()

	doStep1()
	r.Done("doStep1")

	doStep2()
	r.Done("doStep2")

	doStep3()
	r.Done("doStep3")
}

And in case of concurrency, the code would look much simpler too:

func doSomething() {
	r := timeutil.NewRecorder("doSomething")
	defer func() { fmt.Println(r.Info()) }()

	doStep1()
	r.Done("doStep1")

	last := r.Last()
	go func() {
		doStep2()
		r.DoneSince("doStep2", last)
	}()

	doStep3()
	r.Done("doStep3")
}

The result would look like:

context:doSomething, duration:4s, spans:map[doStep1:1s doStep2:2s doStep3:3s], meta:map[]

Summary

With just some very basic technique we are able build a very useful time measurement helper in Go. You can take this to further steps by integrate it into a middleware to measure performance of a REST API call or gRPC call.

For any discussion, please leave comments below.