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

sis.samplingInSeconds and sis.printAtMinutes() running in different goroutines cause DATA RACE #819

Closed
icey129 opened this issue Apr 27, 2022 · 0 comments · Fixed by #820
Labels
enhancement New feature or request

Comments

@icey129
Copy link
Contributor

icey129 commented Apr 27, 2022

- 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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
enhancement New feature or request
Projects
None yet
2 participants