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)
}
CodeConcurrency
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)
}
CodeProduction 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")
}
PlaygroundAnd 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")
}
PlaygroundThe 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.