sis.samplingInSeconds and sis.printAtMinutes() running in different goroutines cause DATA RACE #819
Description
- What did you do (The steps to reproduce)?
Run the following test with go test -race
func TestNewStatsManager(t *testing.T) {
stats := NewStatsManager()
st := time.Now()
for {
stats.increasePullTPS("rocketmq", "default", 1)
time.Sleep(500*time.Millisecond)
if time.Now().Sub(st) > 5*time.Minute {
break
}
}
stats.ShutDownStat()
}
The DATA RACE will print on terminal
- What did you expect to see?
Run the executable file generated by go build -race won't cause DATA RACE
- What did you see instead?
See the DATA RACE
WARNING: DATA RACE
Read at 0x00c000538028 by goroutine 230:
container/list.(*List).Len()
/usr/local/go1.17.3/src/container/list/list.go:66 +0xc7
github.com/apache/rocketmq-client-go/v2/consumer.computeStatsData()
/home/icey/lmm/v9-git/miot-services/lmm/rocketmq-client-go/consumer/statistics.go:143 +0xd5
github.com/apache/rocketmq-client-go/v2/consumer.(*statsItem).printAtMinutes()
/home/icey/lmm/v9-git/miot-services/lmm/rocketmq-client-go/consumer/statistics.go:426 +0x5e
github.com/apache/rocketmq-client-go/v2/consumer.(*statsItemSet).printAtMinutes.func1()
/home/icey/lmm/v9-git/miot-services/lmm/rocketmq-client-go/consumer/statistics.go:285 +0x47
sync.(*Map).Range()
/usr/local/go1.17.3/src/sync/map.go:346 +0x205
github.com/apache/rocketmq-client-go/v2/consumer.(*statsItemSet).printAtMinutes()
/home/icey/lmm/v9-git/miot-services/lmm/rocketmq-client-go/consumer/statistics.go:283 +0x3b
github.com/apache/rocketmq-client-go/v2/consumer.(*statsItemSet).init.func4()
/home/icey/lmm/v9-git/miot-services/lmm/rocketmq-client-go/consumer/statistics.go:224 +0x112
github.com/apache/rocketmq-client-go/v2/primitive.WithRecover()
/home/icey/lmm/v9-git/miot-services/lmm/rocketmq-client-go/primitive/base.go:100 +0x52
github.com/apache/rocketmq-client-go/v2/consumer.(*statsItemSet).init·dwrap·21()
/home/icey/lmm/v9-git/miot-services/lmm/rocketmq-client-go/consumer/statistics.go:215 +0x39
Previous write at 0x00c000538028 by goroutine 227:
container/list.(*List).insert()
/usr/local/go1.17.3/src/container/list/list.go:98 +0x518
container/list.(*List).insertValue()
/usr/local/go1.17.3/src/container/list/list.go:104 +0x1bf
container/list.(*List).PushBack()
/usr/local/go1.17.3/src/container/list/list.go:155 +0x27e
github.com/apache/rocketmq-client-go/v2/consumer.(*statsItem).samplingInSeconds()
/home/icey/lmm/v9-git/miot-services/lmm/rocketmq-client-go/consumer/statistics.go:389 +0x145
github.com/apache/rocketmq-client-go/v2/consumer.(*statsItemSet).samplingInSeconds.func1()
/home/icey/lmm/v9-git/miot-services/lmm/rocketmq-client-go/consumer/statistics.go:261 +0x47
sync.(*Map).Range()
/usr/local/go1.17.3/src/sync/map.go:346 +0x205
github.com/apache/rocketmq-client-go/v2/consumer.(*statsItemSet).samplingInSeconds()
/home/icey/lmm/v9-git/miot-services/lmm/rocketmq-client-go/consumer/statistics.go:259 +0x3b
github.com/apache/rocketmq-client-go/v2/consumer.(*statsItemSet).init.func1()
/home/icey/lmm/v9-git/miot-services/lmm/rocketmq-client-go/consumer/statistics.go:184 +0xc6
github.com/apache/rocketmq-client-go/v2/primitive.WithRecover()
/home/icey/lmm/v9-git/miot-services/lmm/rocketmq-client-go/primitive/base.go:100 +0x52
github.com/apache/rocketmq-client-go/v2/consumer.(*statsItemSet).init·dwrap·18()
/home/icey/lmm/v9-git/miot-services/lmm/rocketmq-client-go/consumer/statistics.go:176 +0x39
Goroutine 230 (running) created at:
github.com/apache/rocketmq-client-go/v2/consumer.(*statsItemSet).init()
/home/icey/lmm/v9-git/miot-services/lmm/rocketmq-client-go/consumer/statistics.go:215 +0x3d0
github.com/apache/rocketmq-client-go/v2/consumer.newStatsItemSet()
/home/icey/lmm/v9-git/miot-services/lmm/rocketmq-client-go/consumer/statistics.go:171 +0x51c
github.com/apache/rocketmq-client-go/v2/consumer.NewStatsManager()
/home/icey/lmm/v9-git/miot-services/lmm/rocketmq-client-go/consumer/statistics.go:46 +0x51d
github.com/apache/rocketmq-client-go/v2/consumer.TestNewStatsManager()
/home/icey/lmm/v9-git/miot-services/lmm/rocketmq-client-go/consumer/statistics_test.go:217 +0x29
testing.tRunner()
/usr/local/go1.17.3/src/testing/testing.go:1259 +0x22f
testing.(*T).Run·dwrap·21()
/usr/local/go1.17.3/src/testing/testing.go:1306 +0x47
Goroutine 227 (running) created at:
github.com/apache/rocketmq-client-go/v2/consumer.(*statsItemSet).init()
/home/icey/lmm/v9-git/miot-services/lmm/rocketmq-client-go/consumer/statistics.go:176 +0x12b
github.com/apache/rocketmq-client-go/v2/consumer.newStatsItemSet()
/home/icey/lmm/v9-git/miot-services/lmm/rocketmq-client-go/consumer/statistics.go:171 +0x51c
github.com/apache/rocketmq-client-go/v2/consumer.NewStatsManager()
/home/icey/lmm/v9-git/miot-services/lmm/rocketmq-client-go/consumer/statistics.go:46 +0x51d
github.com/apache/rocketmq-client-go/v2/consumer.TestNewStatsManager()
/home/icey/lmm/v9-git/miot-services/lmm/rocketmq-client-go/consumer/statistics_test.go:217 +0x29
testing.tRunner()
/usr/local/go1.17.3/src/testing/testing.go:1259 +0x22f
testing.(*T).Run·dwrap·21()
/usr/local/go1.17.3/src/testing/testing.go:1306 +0x47
Please tell us about your environment:
- What is your OS?
Linux ubuntu 16.04
- What is your client version?
v2.1.0
Other information (e.g. detailed explanation, logs, related issues, suggestions on how to fix, etc):
When run statsItemSet init() will start several goroutines to run sis.samplingInSeconds() and sis.printAtMinutes().
The samplingInSeconds() func will write csListMinute
func (si *statsItem) samplingInSeconds() {
si.csListMinuteLock.Lock()
defer si.csListMinuteLock.Unlock()
si.csListMinute.PushBack(callSnapshot{
timestamp: time.Now().Unix() * 1000,
time: atomic.LoadInt64(&si.times),
value: atomic.LoadInt64(&si.value),
})
if si.csListMinute.Len() > 7 {
si.csListMinute.Remove(si.csListMinute.Front())
}
}
While printAtMinutes() func call computeStatsData() will read csListMinute
func (si *statsItem) printAtMinutes() {
ss := computeStatsData(si.csListMinute)
rlog.Info("Stats In One Minute, SUM: %d TPS: AVGPT: %.2f", map[string]interface{}{
"statsName": si.statsName,
"statsKey": si.statsKey,
"SUM": ss.sum,
"TPS": fmt.Sprintf("%.2f", ss.tps),
"AVGPT": ss.avgpt,
})
}
var csListLock sync.Mutex
func computeStatsData(csList *list.List) statsSnapshot {
csListLock.Lock()
defer csListLock.Unlock()
tps, avgpt, sum := 0.0, 0.0, int64(0)
if csList.Len() > 0 {
first := csList.Front().Value.(callSnapshot)
last := csList.Back().Value.(callSnapshot)
sum = last.value - first.value
tps = float64(sum*1000.0) / float64(last.timestamp-first.timestamp)
timesDiff := last.time - first.time
if timesDiff > 0 {
avgpt = float64(sum*1.0) / float64(timesDiff)
}
}
return statsSnapshot{
tps: tps,
avgpt: avgpt,
sum: sum,
}
}
In samplingInSeconds() use csListMinuteLock while computeStatsData() use a global Mutex to lock. So read and write in different goroutine will cause DATA RACE.