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

Issue

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.

Answered By – jub0bs

Answer Checked By – Willingham (GoLangFix Volunteer)

Leave a Reply

Your email address will not be published.