Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

runtime/race: data race hidden by fake synchronization #8320

Closed
remyoudompheng opened this issue Jul 2, 2014 · 3 comments
Closed

runtime/race: data race hidden by fake synchronization #8320

remyoudompheng opened this issue Jul 2, 2014 · 3 comments
Labels
FrozenDueToAge RaceDetector Unfortunate

Comments

@remyoudompheng
Copy link
Contributor 

What steps will reproduce the problem?
1. go run -race the following program:

http://play.golang.org/p/8ju-c1opip

package main

import (
    "log"
    "math"
    "sync"
    //"time"
)

type T struct {
    Type  string
    Field string
}

type U struct {
    Arg string
}

func main() {
    args := []T{
        {Type: "constant", Field: "A"},
        {Type: "constant", Field: "B"},
        {Type: "constant", Field: "C"},
        {Type: "constant", Field: "D"},
        {Type: "constant", Field: "E"},
        {Type: "constant", Field: "F"},
        {Type: "constant", Field: "G"},
        {Type: "constant", Field: "H"},
    }
    wg := new(sync.WaitGroup)
    wg.Add(len(args))
    for _, arg := range args {
        log.Printf("doing arg: %+v", arg)
        local := U{Arg: arg.Field}
        go func() {
            defer wg.Done()
            _ = busy()
            log.Printf("%+v", local)
            if arg.Type != "constant" {
                log.Printf("argh!")
            }
        }()
        //time.Sleep(100 * time.Millisecond)
    }
    wg.Wait()
}

func busy() float64 {
    x := 0.0
    for i := 1; i < 1000000; i++ {
        x += math.Log(float64(i))
    }
    return x
}

What is the expected output? What do you see instead?

Expected:

2014/07/02 23:40:47 doing arg: {Type:constant Field:A}
2014/07/02 23:40:47 doing arg: {Type:constant Field:B}
2014/07/02 23:40:47 doing arg: {Type:constant Field:C}
2014/07/02 23:40:47 doing arg: {Type:constant Field:D}
2014/07/02 23:40:47 doing arg: {Type:constant Field:E}
2014/07/02 23:40:47 doing arg: {Type:constant Field:F}
2014/07/02 23:40:47 doing arg: {Type:constant Field:G}
2014/07/02 23:40:47 doing arg: {Type:constant Field:H}
==================
WARNING: DATA RACE
Write by main goroutine:
  main.main()
      /tmp/w.go:32 +0x33b

Previous read by goroutine 5:
  main.func·001()
      /tmp/w.go:39 +0x15f

Goroutine 5 (finished) created at:
  main.main()
      /tmp/w.go:42 +0x532
==================
2014/07/02 23:40:47 {Arg:A}
2014/07/02 23:40:47 {Arg:B}
2014/07/02 23:40:47 {Arg:C}
2014/07/02 23:40:47 {Arg:D}
2014/07/02 23:40:47 {Arg:E}
2014/07/02 23:40:47 {Arg:F}
2014/07/02 23:40:47 {Arg:G}
2014/07/02 23:40:47 {Arg:H}

Instead:

2014/07/02 23:40:47 doing arg: {Type:constant Field:A}
2014/07/02 23:40:47 doing arg: {Type:constant Field:B}
2014/07/02 23:40:47 doing arg: {Type:constant Field:C}
2014/07/02 23:40:47 doing arg: {Type:constant Field:D}
2014/07/02 23:40:47 doing arg: {Type:constant Field:E}
2014/07/02 23:40:47 doing arg: {Type:constant Field:F}
2014/07/02 23:40:47 doing arg: {Type:constant Field:G}
2014/07/02 23:40:47 doing arg: {Type:constant Field:H}
2014/07/02 23:40:47 {Arg:A}
2014/07/02 23:40:47 {Arg:B}
2014/07/02 23:40:47 {Arg:C}
2014/07/02 23:40:47 {Arg:D}
2014/07/02 23:40:47 {Arg:E}
2014/07/02 23:40:47 {Arg:F}
2014/07/02 23:40:47 {Arg:G}
2014/07/02 23:40:47 {Arg:H}


Please use labels and text to provide additional information.
@remyoudompheng
Copy link
Contributor Author

Comment 1:

Uncommenting the time.Sleep restores race detection:
2014/07/02 23:39:39 doing arg: {Type:constant Field:A}
2014/07/02 23:39:39 {Arg:A}
==================
WARNING: DATA RACE
Write by main goroutine:
  main.main()
      /tmp/w.go:32 +0x33b
Previous read by goroutine 5:
  main.func·001()
      /tmp/w.go:39 +0x15f
Goroutine 5 (finished) created at:
  main.main()
      /tmp/w.go:42 +0x532
==================
2014/07/02 23:39:39 doing arg: {Type:constant Field:B}
2014/07/02 23:39:39 {Arg:B}
2014/07/02 23:39:39 doing arg: {Type:constant Field:C}
2014/07/02 23:39:39 {Arg:C}
2014/07/02 23:39:39 doing arg: {Type:constant Field:D}
2014/07/02 23:39:39 {Arg:D}
2014/07/02 23:39:40 doing arg: {Type:constant Field:E}
2014/07/02 23:39:40 {Arg:E}
2014/07/02 23:39:40 doing arg: {Type:constant Field:F}
2014/07/02 23:39:40 {Arg:F}
2014/07/02 23:39:40 doing arg: {Type:constant Field:G}
2014/07/02 23:39:40 {Arg:G}
2014/07/02 23:39:40 doing arg: {Type:constant Field:H}
2014/07/02 23:39:40 {Arg:H}
Found 1 data race(s)

@ianlancetaylor
Copy link
Contributor

Comment 2:

Labels changed: added repo-main, release-none.

@dvyukov
Copy link
Member

dvyukov commented Jul 3, 2014

Comment 3:

I've run it as:
$ GORACE=atexit_sleep_ms=0 GOMAXPROCS=4 while ./race; do true; done
and it detected the race in several seconds.
I am not sure it's possible to do something here to improve the situation. It's the
nature of happens-before-based race detectors. And It's the cost for that you don't need
to add any manual annotations to the code and the race detector understands all
synchronization patterns (not just this data is protected by this mutex).

Status changed to Unfortunate.

@golang golang locked and limited conversation to collaborators Jun 25, 2016
This issue was closed.
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge RaceDetector Unfortunate
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@remyoudompheng @dvyukov @ianlancetaylor @gopherbot