loopsgopointersgoroutinedata-race

Unexpected behavior from launching a method call on a loop variable as a goroutine


I read this article and decided to repeat such behavior myself and experiment with that:

package main

import (
    "fmt"
    "time"
)

type User struct {
    i    int
    token string
}

func NewUser(i int, token string) User {
    user := User{token: fmt.Sprint(i), i: i}
    return user
}

func (u *User) PrintAddr() {
    fmt.Printf("%d (PrintAddr): %p\n", u.i, u)
}

func main() {
    users := make([]User, 4)
    for i := 0; i < 4; i++ {
        user := NewUser(i, "")
        users[i] = user
    }
    
    for i, user := range users {
        go user.PrintAddr()
        go users[i].PrintAddr()
    }
    time.Sleep(time.Second)
}

(Playground)

Here is the code output:

1 (PrintAddr): 0xc000056198
2 (PrintAddr): 0xc0000561b0
0 (PrintAddr): 0xc000056180
3 (PrintAddr): 0xc00000c030
3 (PrintAddr): 0xc00000c030
3 (PrintAddr): 0xc00000c030
3 (PrintAddr): 0xc00000c030
3 (PrintAddr): 0xc0000561c8

I also don't understand, why are 4 of 5 3 (PrintAddr) are 0xc00000c030, and the last one is different?


However, if I use a pointer array instead of value array, like this,

func NewUser(i int, token string) *User {
    user := &User{token: fmt.Sprint(i), i: i}
    return user
}
// -snip-
func main() {
    users := make([]*User, 4)
    // -snip-

(Playground)

then everything's fine here and each entry is printed exactly 2 times with the same address:

1 (PrintAddr): 0xc0000ae030
3 (PrintAddr): 0xc0000ae060
2 (PrintAddr): 0xc0000ae048
2 (PrintAddr): 0xc0000ae048
3 (PrintAddr): 0xc0000ae060
1 (PrintAddr): 0xc0000ae030
0 (PrintAddr): 0xc0000ae018
0 (PrintAddr): 0xc0000ae018

But why did the situation in the article not apply here and I didn't get many 3 (PrintAddr) instead?


Solution

  • Problem

    Your first version has a synchronisation bug, which manifests itself as a data race:

    $ go run -race main.go
    0 (PrintAddr): 0xc0000b4018
    0 (PrintAddr): 0xc0000c2120
    ==================
    WARNING: DATA RACE
    Write at 0x00c0000b4018 by main goroutine:
      main.main()
          redacted/main.go:29 +0x1e5
    
    Previous read at 0x00c0000b4018 by goroutine 7:
      main.(*User).PrintAddr()
          redacted/main.go:19 +0x44
    
    Goroutine 7 (finished) created at:
      main.main()
          redacted/main.go:30 +0x244
    ==================
    1 (PrintAddr): 0xc0000b4018
    1 (PrintAddr): 0xc0000c2138
    2 (PrintAddr): 0xc0000b4018
    2 (PrintAddr): 0xc0000c2150
    3 (PrintAddr): 0xc0000b4018
    3 (PrintAddr): 0xc0000c2168
    Found 1 data race(s)
    

    The for loop (line 29) keeps updating loop variable user while (i.e. in a concurrent manner without proper synchronisation) the PrintAddr method accesses it via its pointer receiver (line 19). Note that if you don't start user.PrintAddr() as a goroutine on line 30, the problem goes away.

    The problem and a solution to it are actually given at the bottom of the Wiki you link to.

    But why did the situation in the article not apply here and I didn't get many 3 (PrintAddr) instead?

    That synchronisation bug is a source of undesired undeterminism. In particular, you cannot predict how many times (if any) 3 (PrintAddr) will be printed, and that number may vary from one execution to the next. In fact, scroll up and see for yourself: in my execution with the race detector on, the output happened to feature two of each integer between 0 and 3, despite the bug; but there's no guarantee for that.

    Solution

    Simply shadow loop variable user at the top of the loop and the problem goes away:

    for i, user := range users {
        user := user // <---
        go user.PrintAddr()
        go users[i].PrintAddr()
    }
    

    PrintAddr will now operate on the innermost user variable, which is not updated by the for loop on line 29.

    (Playground)

    Addendum

    You should also use a wait group to wait for all your goroutines to finish. time.Sleep is no way to coordinate goroutines.