Redigo concurrent Set gives data race

Question

I'm running this test against my redigo functions to see if it supports massive concurrent writes, here're the code

import (
    "github.com/gomodule/redigo/redis"
    "log"
    "os"
)

// Redis connection pool
var RedisPool *redis.Pool

func InitPool() {
    RedisPool = &redis.Pool{
        MaxIdle:   80,
        MaxActive: 12000,
        Dial: func() (redis.Conn, error) {
            conn, err := redis.Dial("tcp", "127.0.0.1:6379")
            if err != nil {
                log.Printf("ERROR: fail init redis: %s", err.Error())
                os.Exit(1)
            }
            return conn, err
        },
    }
}

func ClosePool() error {
    return RedisPool.Close()
}

func Set(key string, val string) error {
    // get conn and put back when exit from method
    conn := RedisPool.Get()
    defer conn.Close()

    _, err := conn.Do("SET", key, val)
    if err != nil {
        log.Printf("ERROR: fail set key %s, val %s, error %s", key, val, err.Error())
        return err
    }

    return nil
}

func TestManySets(t *testing.T) {
    InitPool()
    defer ClosePool()

    var wg sync.WaitGroup
    numOfOperations := 1000
    for i := 0; i < numOfOperations; i++ {
        wg.Add(1)
        go func() {
            err := Set("key", strconv.Itoa(i))
            if err != nil {
                t.Errorf("error when setting key value: %s", err)
            }
            wg.Done()
        }()
    }
    wg.Wait()

    result, err := Get("key")
    if err != nil {
        t.Errorf("error when getting key value: %s", err)
    }
    t.Logf("result: %s", result)
}

When running the test with go test -run TestManySets /path/to/package -count 1 -v I'm getting A LOT of EOF error;

and when running the test with -race, i.e. go test -race -run TestManySets /path/to/package -count 1 -v I'm getting a lot of data race detected, anyone could kindly point out to me how I could make things right?

Below is the data race log:

ycx@DESKTOP-NBD349L:/mnt/c/Users/robbi/Projects/GoGameServer$ go test -race -run TestManySets visiontech.com/adapter -count 1 -v
=== RUN   TestManySets
==================
WARNING: DATA RACE
Read at 0x00c00009ab10 by goroutine 7:
  visiontech.com/adapter.TestManySets.func1()
      /home/ycx/Projects/GoGameServer/src/visiontech.com/adapter/redis_test.go:48 +0x3c

Previous write at 0x00c00009ab10 by goroutine 6:
  visiontech.com/adapter.TestManySets()
      /home/ycx/Projects/GoGameServer/src/visiontech.com/adapter/redis_test.go:45 +0x14c
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:865 +0x163

Goroutine 7 (running) created at:
  visiontech.com/adapter.TestManySets()
      /home/ycx/Projects/GoGameServer/src/visiontech.com/adapter/redis_test.go:47 +0x128
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:865 +0x163

Goroutine 6 (running) created at:
  testing.(*T).Run()
      /usr/local/go/src/testing/testing.go:916 +0x65a
  testing.runTests.func1()
      /usr/local/go/src/testing/testing.go:1157 +0xa8
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:865 +0x163
  testing.runTests()
      /usr/local/go/src/testing/testing.go:1155 +0x523
  testing.(*M).Run()
      /usr/local/go/src/testing/testing.go:1072 +0x2eb
  main.main()
      _testmain.go:62 +0x222
==================
--- FAIL: TestManySets (10.08s)
    redis_test.go:62: result: 1000
    testing.go:809: race detected during execution of test
FAIL
FAIL    visiontech.com/adapter  10.098s
ycx@DESKTOP-NBD349L:/mnt/c/Users/robbi/Projects/GoGameServer$

And redis_test.go line 47 is where the Set happens in the code above.

you got to share the data races detection output so we might try to help you further. — , Sep 23 '19 at 12:05
When you get a data race, the output tells you exactly where--which two files/lines had the race. Start by reading that. If you need help, please include that output in your question. — Jonathan Hall, Sep 23 '19 at 12:10
This code snippet creates 1000 goroutines that does redis SET command, so as you can see the data race happens here `err := Set("key", strconv.Itoa(i))`. — dulan, Sep 23 '19 at 12:36
The race is because your for loop is updating `i` while your goroutines are reading `i` simultaneously. — Jonathan Hall, Sep 23 '19 at 12:41
https://github.com/golang/go/wiki/CommonMistakes#using-goroutines-on-loop-iterator-variables — Peter, Sep 23 '19 at 12:44
Note line 47 is not where Set happens... it's where `go func() {` happens. — Jonathan Hall, Sep 23 '19 at 12:58

score 1 · Accepted Answer · answered Sep 23 '19 at 12:43

The race is because your for loop is updating i while your goroutines are reading i simultaneously. One way to solve this is to pass i into your goroutine function:

for i := 0; i < numOfOperations; i++ {
    wg.Add(1)
    go func(i int) {                             // <----------- CHANGE THIS
        err := Set("key", strconv.Itoa(i))
        if err != nil {
            t.Errorf("error when setting key value: %s", err)
        }
        wg.Done()
    }(i)                                         // <----------- AND THIS
}

This way you no longer have a closure over i, and the i inside your goroutine function is a distinct value that can be read (or written) without interference from the outside.

This also solves another bug, that the race detector won't find: in a for loop, the incremented variable is re-used, which means your current version is actually unwittingly using the same i value in many cases, and skipping over others. See here for more on this.

How dump I am... I thought I'm using redigo incorrectly, thanks man! — dulan, Sep 23 '19 at 12:50
If you look closely at the race detector output, it points you in the right direction: "Read at ... redis_test.go:48" and "Previous write at ... redis_test.go:45" This narrows it down to variables that are written on line 45, and read on 48. The only variable that fits that description is `i`. — Jonathan Hall, Sep 23 '19 at 12:54

Redigo concurrent Set gives data race

1 Answers1