Data race in Go: Why does it happen below 10-11ms?

Question

Here is the code I ran:

package main

import (
    "fmt"
    "time"
)

const delay = 9 * time.Millisecond

func main() {
    n := 0
    go func() {
        time.Sleep(delay)
        n++
    }()
    fmt.Println(n)
}

Here is the command I used:

go run -race data_race_demo.go

Here is the behavior I noticed:

• With delay set to 9ms or lower, data race is always detected (program throws Found 1 data race(s))
• With delay set to 12ms or higher, data race is never detected (program simply prints 0)
• With delay set to 10 to 11ms, data race occurs intermittently (that is, sometimes prints 0 and sometimes throws Found 1 data race(s))

Why does this happen at around 10-11ms?

I'm using Go 1.16.3 on darwin/amd64, if that matters.

Answer 1

You have 2 goroutines: the main and the one you launch. They access the n variable (and one is a write) without synchronization: that's a data race.

Whether this race is detected depends on whether this racy access occurs. When the main() function ends, your app ends as well, it does not wait for other non-main goroutines to finish.

If you increase the sleep delay, main() will end sooner than the end of sleep and will not wait for the n++ racy write to occur, so nothing is detected. If sleep is short, shorter than the fmt.Prinln() execution time, the racy write occurs and is detected.

There's nothing special about the 10ms. That's just the approximated time it takes to execute fmt.Println() and terminate your app in your environment. If you do other "lengthy" task before the Println() statement, such as this:

for i := 0; i < 5_000_000_000; i++ {
}
fmt.Println(n)

The race will be detected even with 50ms sleep too (because that loop will take some time to execute, allowing the racy write to occur before n is read for the fmt.Println() call and the app terminated). (A simple time.Sleep() would also do, I just didn't want anyone to draw the wrong conclusion that they "interact" with each other somehow.)