I want to time a function to see how long it takes to execute. Unfortunately, waiting for <-ctx.Done() (produced from context.WithTimeout) seems to take a long time – roughly an extra 1ms than it should (on my machine). Consider this example, where I time the function taskWithContext. The context is set to timeout after 50ms, which is way more than taskWithContext needs to finish. Unfortunately, the result is that it takes around 51.2 ms (which is 1.2 ms more than the set expected timeout). Am I missing something, or is there a way to make <-ctx.Done() faster?
func main() {
timeout := 50 * time.Millisecond
ctx, cancel := context.WithTimeout(context.Background(), timeout)
defer cancel()
start := time.Now()
go taskWithContext(ctx)
<-ctx.Done()
finish := time.Since(start)
fmt.Printf("Finished in %v\n", finish)
}
func taskWithContext(ctx context.Context) {
doWork()
fmt.Println("Task completed successfully")
}
func doWork() {
total := 0
for i := 0; i < 500000; i++ {
total += i
}
}
For comparison, running a similar function, still in a separate goroutine takes around 200µs (note the difference in magnitude: 10^-6 vs 10^-3 seconds). The difference is the context is cancelled by the goroutine itself after it finishes the work (however, this is not ideal in practice).
func main() {
ctx, cancel := context.WithTimeout(context.Background(), 50*time.Millisecond)
defer cancel()
start := time.Now()
go taskWithContext(ctx, cancel)
<-ctx.Done()
finish := time.Since(start)
fmt.Printf("Finished in %v\n", finish)
}
func taskWithContext(ctx context.Context, cancel func()) {
defer cancel()
doWork()
fmt.Println("Task completed successfully")
}
func doWork() {
total := 0
for i := 0; i < 500000; i++ {
total += i
}
}
This timing is similar to the timing taken for a direct computation, where no goroutines are created:
func main() {
start := time.Now()
task()
finish := time.Since(start)
fmt.Printf("Finished in %v\n", finish)
}
func task() {
doWork()
fmt.Println("Task completed successfully")
}
func doWork() {
total := 0
for i := 0; i < 500000; i++ {
total += i
}
}
Is there a better way (than the first snippet), to handle contexts when performance is crucial?
<-ctx.Done() always waits until the context is canceled or times out. It is usually used inside a select block to exit on a canceled context condition.
To wait for goroutines to complete, you can use sync.Waitgroup instead (or alternatively, the errgroup package that is similar to Waitgroup but enables your goroutines to return errors.)
The snippets are minimal reproducible example, so in practice it makes sense to use wait for <-ctx.Done() in a select block (and similarly to use sync.Waitgroup).
However, I am more curious on why does using <-ctx.Done() that is produced by a timer creates a lot of extra overhead.
Sorry, I was on the wrong track. Now I see what you mean.
I don’t know why ctx.Done() adds 1.2 extra milliseconds. However, consider that ctx.Done() triggers when a context times out or is canceled by another goroutine. Both events basically tell the goroutine that there is nothing to do anymore because another goroutine finished the job (-> cancel()) or a critical component failed to respond (-> timeout). In any case, the goroutine that receives a <-ctx.Done() is outside the critical path of the app. The only job left is to clean up and exit. Hence the performance of <-ctx.Done() should be of minor importance in typical scenarios.
You’re right, normally you do not care about that, however in my case, I have an application that spawns a tree of processes and the only reasonable way (that I found so far) to manage them is via context (since it offers a clean way to cancel any stuck processes) – I wish to perform so benchmarking, however the overhead (cause via timeouts) seems to be far from negligible.
I wish to reword my query. Are there any guarantees (e.g. terminate within x% of the originally stated time) on how long timers take to use. Or, why does using a timer take so much extra time?
Take this example:
const timeout = 50 * time.Millisecond
func main() {
ctx, cancel := context.WithTimeout(context.Background(), timeout)
defer cancel()
start := time.Now()
go taskWithContext(ctx, cancel)
<-ctx.Done()
finish := time.Since(start) - timeout
fmt.Printf("Extra time waiting for timer and context cancellation: %v\n", finish)
}
func taskWithContext(ctx context.Context, cancel func()) {
defer cancel()
t := time.NewTimer(timeout)
start := time.Now()
<-t.C // Wait for timeout
finish := time.Since(start) - timeout
fmt.Printf("Extra time waiting for timer: %v\n", finish)
}
When I run it, I get the following output:
// Extra time waiting for timer: 1.032ms
// Extra time waiting for timer and context cancellation: 1.065958ms
Are these timings normal, or do they seem unreasonably long?
I found couple of discussions on GitHub 44608, 44343 and actual explanation, which was added in this update into the time package. This kind of things are related to a lot of factors and in practice they are almost imperceptible. Since go applications does not work like those examples, imho you need to run benchmarking and profiling on your actual code, not on the hypothetical pseudo one if you are looking for performance improvements.