go test -race adds 1 second execution time to every package tested

[gordallott]

Please answer these questions before submitting your issue. Thanks!

What version of Go are you using (go version)?

go1.8

What operating system and processor architecture are you using (go env)?

linux/amd64

What did you do?

creating a simple test

 package main                                                                                                                                                 
                                                                                                                                                              
 import (                                                                                                                                                     
     "testing"                                                                                                                                                
 )                                                                                                                                                            
                                                                                                                                                              
 func TestFoo(t *testing.T) {                                                                                                                                 
     println("okay!")                                                                                                                                           
 }                                                                                                                                                            
                                                                                                                                                              
 func TestBar(t *testing.T) {                                                                                                                                 
     println("ohno")                                                                                                                                            
 }         

And then running it with go test -race . will add an extra second to the execution time compared to running without race. This happens for every single package tested.
Ultimately this means for a test runner that runs many tests over many packages it takes much longer to run the test suite with -race than without, with every package added adding another second to the execution time

This extra second per package seems unrelated to cpu/memory/disk performance and seems uniformly one second over every machine we test with. Trom high powered machines to low powered machines.

Obviously some aspect of performance loss is expected with the race detector running but this seems unrelated to that and more related to an artificial wait being introduced before running the tests in a package. I've never seen it add less or more than one second to a test regardless of the machine.

What did you expect to see?

go test -v -race .                                                                                                                         
=== RUN   TestFoo
okay!
--- PASS: TestFoo (0.00s)
=== RUN   TestBar
ohno
--- PASS: TestBar (0.00s)
PASS
ok  	_/tmp/gotest	0.002s

What did you see instead?

go test -v -race .                                                                                                                   
=== RUN   TestFoo
okay!
--- PASS: TestFoo (0.00s)
=== RUN   TestBar
ohno
--- PASS: TestBar (0.00s)
PASS
ok  	_/tmp/gotest	1.008s

[mvdan]

Same on tip (go version devel +61336b78c1 Sun May 14 00:27:25 2017 +0000 linux/amd64).

I could not find a previous issue for this, and I'm surprised I never noticed this extra second. I agree that it looks like a wait/sleep, and not just extra CPU work. In the last second of my go test -race -v run (once the PASS line has been printed), my CPU load drops from ~80% to ~10%.

I would hope this is on purpose and supposed to catch some things in go test -race though, like goroutine leaks that may do work after the main test goroutine is done. I have no idea though, so this is purely speculation.

[cespare]

@mvdan's intuition is correct. You can set the sleep time to zero using an environment variable:

GORACE=atexit_sleep_ms=0 go test -race

@dvyukov gave the reasoning for the 1s default here: https://groups.google.com/d/msg/golang-nuts/HBJQaijCwGo/P1NNQN7wyMAJ

[mvdan]

Thanks @cespare - having this issue in the tracker with all the info for posterity should help other people in similar situations.

[mvdan]

For those landing in this issue in the future, like I did just now six years later (:scream:), see the docs at https://go.dev/doc/articles/race_detector for the list of options accepted by GORACE.