Fix race between `OnDemandHousekeeping` and `housekeepingTick` #2755

pkagrawal · 2020-12-07T18:12:54Z

This fixes the data race between the functions which could be running
in different goroutines.

Signed-off-by: Pradyumna Agrawal pradyumnaa@vmware.com

This fixes the data race between the functions which could be running in different goroutines. Signed-off-by: Pradyumna Agrawal <pradyumnaa@vmware.com>

k8s-ci-robot · 2020-12-07T18:13:03Z

Hi @pkagrawal. Thanks for your PR.

I'm waiting for a google member to verify that this patch is reasonable to test. If it is, they should reply with /ok-to-test on its own line. Until that is done, I will not automatically test new commits in this PR, but the usual testing commands by org members will still work. Regular contributors should join the org to skip this step.

Once the patch is verified, the new status will be reflected by the ok-to-test label.

I understand the commands that are listed here.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

pkagrawal · 2020-12-07T18:13:24Z

Fixes #2754

Signed-off-by: Pradyumna Agrawal <pradyumnaa@vmware.com>

…datedTime) Signed-off-by: Pradyumna Agrawal <pradyumnaa@vmware.com>

iwankgb · 2020-12-07T21:39:36Z

/ok-to-test

iwankgb · 2020-12-07T21:52:35Z

manager/container.go

@@ -555,6 +558,8 @@ func (cd *containerData) housekeepingTick(timer <-chan time.Time, longHousekeepi
 		klog.V(3).Infof("[%s] Housekeeping took %s", cd.info.Name, duration)
 	}
 	cd.notifyOnDemand()
+	cd.lock.Lock()


I believe that call above this line is responsible for synchronization with containerData.OnDemandHousekeeping(). Lock that you are trying to introduce looks redundant to me. Are you able to provide a test case that help race to manifest?

I don't have a test case, but we were using cadvisor and our race detector tripped up:

WARNING: DATA RACE Read at 0x00c0001e7a50 by goroutine 30: github.com/google/cadvisor/manager.(*containerData).OnDemandHousekeeping() vendor/github.com/google/cadvisor/manager/container.go:141 +0x9b github.com/google/cadvisor/manager.(*manager).getRequestedContainers.func1() vendor/github.com/google/cadvisor/manager/manager.go:741 +0x64 Previous write at 0x00c0001e7a50 by goroutine 130: github.com/google/cadvisor/manager.(*containerData).housekeepingTick() vendor/github.com/google/cadvisor/manager/container.go:558 +0x34c github.com/google/cadvisor/manager.(*containerData).housekeeping() vendor/github.com/google/cadvisor/manager/container.go:494 +0x304

Thank you 🙇. I think we should use single synchronisation mechanism in this case. I wonder if moving notifyOnDemand() call a bit lower and applying similar change to OnDemandHousekeeping() would not solve the issue.

Thanks for looking. I'm not quite sure that I follow what you mean by single synchronization. OnDemandHousekeeping is an external API so anyone can call it, and it can potentially race with housekeepingTick when both try and access statsLastUpdatedTime. Access to this variable should be guarded by some mutual exclusion - right?

@iwankgb Can you take a look at this again? Thanks!

@pkagrawal I don't think I will be able to look at this issue again before coming weekend.

iwankgb · 2020-12-12T15:54:35Z

@pkagrawal I was trying to replicate your problem and I simply can do this. I wrote following simple test:

func TestOnDemandHousekeepingRace(t *testing.T) {
	statsList := itest.GenerateRandomStats(1, 4, 1*time.Second)
	stats := statsList[0]

	//cd, mockHandler, _, fakeClock := newTestContainerData(t)
	cd, mockHandler, _, _ := newTestContainerData(t)
	mockHandler.On("GetStats").Return(stats, nil)

	wg := sync.WaitGroup{}
	wg.Add(1)

	err := cd.Start()
	assert.NoError(t, err)

	go func() {
		t.Log("starting on demand goroutine")
		for i := 0; i < 100000; i++  {
			t.Logf("on demand iteration %d", i)
			cd.OnDemandHousekeeping(0 * time.Second)
		}
		wg.Done()
	}()
	wg.Wait()
}

and I can't get any race:

=== RUN   TestOnDemandHousekeepingRace
--- PASS: TestOnDemandHousekeepingRace (0.14s)
PASS
ok  	github.com/google/cadvisor/manager	1.260s

iwankgb · 2020-12-29T15:55:52Z

@pkagrawal I have just realized that I was trying to use race detector on linux/arm64 and:

     -race
           enable data race detection.
           Supported only on linux/amd64, freebsd/amd64, darwin/amd64 and windows/amd64.

Let me take one more look at this problem.

iwankgb · 2020-12-29T16:59:54Z

I do confirm that this is a real issue:

[root@fedora-s-4vcpu-8gb-fra1-01 cadvisor]# uname -m
x86_64
[root@fedora-s-4vcpu-8gb-fra1-01 cadvisor]# GOMAXPROCS=4 go test -v -race -run TestOnDemandHousekeepingRace ./manager/
=== RUN   TestOnDemandHousekeepingRace
    container_test.go:342: starting on demand goroutine
==================
WARNING: DATA RACE
Read at 0x00c0004c6610 by goroutine 108:
  github.com/google/cadvisor/manager.(*containerData).OnDemandHousekeeping()
      /root/go/src/github.com/google/cadvisor/manager/container.go:141 +0x9b
  github.com/google/cadvisor/manager.TestOnDemandHousekeepingRace.func2.1()
      /root/go/src/github.com/google/cadvisor/manager/container_test.go:346 +0x4e

Previous write at 0x00c0004c6610 by goroutine 100:
  github.com/google/cadvisor/manager.(*containerData).housekeepingTick()
      /root/go/src/github.com/google/cadvisor/manager/container.go:558 +0x34c
  github.com/google/cadvisor/manager.(*containerData).housekeeping()
      /root/go/src/github.com/google/cadvisor/manager/container.go:494 +0x304

Goroutine 108 (running) created at:
  github.com/google/cadvisor/manager.TestOnDemandHousekeepingRace.func2()
      /root/go/src/github.com/google/cadvisor/manager/container_test.go:344 +0xaf

Goroutine 100 (running) created at:
  github.com/google/cadvisor/manager.(*containerData).Start()
      /root/go/src/github.com/google/cadvisor/manager/container.go:114 +0x4c
  github.com/google/cadvisor/manager.TestOnDemandHousekeepingRace.func1()
      /root/go/src/github.com/google/cadvisor/manager/container_test.go:336 +0x49
==================
    testing.go:1038: race detected during execution of test
--- FAIL: TestOnDemandHousekeepingRace (0.06s)
=== CONT
    testing.go:1038: race detected during execution of test
FAIL
FAIL	github.com/google/cadvisor/manager	0.119s
FAIL

using following test case:

func TestOnDemandHousekeepingRace(t *testing.T) {
	statsList := itest.GenerateRandomStats(1, 4, 1*time.Second)
	stats := statsList[0]

	//cd, mockHandler, _, fakeClock := newTestContainerData(t)
	cd, mockHandler, _, _ := newTestContainerData(t)
	mockHandler.On("GetStats").Return(stats, nil)

	wg := sync.WaitGroup{}
	wg.Add(1002)

	go func() {
		time.Sleep(10 * time.Millisecond)
		err := cd.Start()
		assert.NoError(t, err)
		wg.Done()
	}()

	go func() {
		t.Log("starting on demand goroutine")
		for i := 0; i < 1000; i++  {
			go func() {
				time.Sleep(1 * time.Microsecond)
				cd.OnDemandHousekeeping(0 * time.Millisecond)
				wg.Done()
			}()
		}
		wg.Done()
	}()
	wg.Wait()
}

iwankgb · 2020-12-29T17:02:19Z

@pkagrawal, could you do the following:

add "Fixes Data race between OnDemandHousekeeping and housekeepingTick #2754" to PR description (otherwise the issue will not be linked)
add a test case to prevent regression (you can use code that I pasted above)

I'm sorry for delaying you work but I had no idea that race detector works on amd64 only.

iwankgb · 2020-12-29T17:02:47Z

@bobbypage, I summon you as this is a bug indeed.

Signed-off-by: Pradyumna Agrawal <pradyumnaa@vmware.com>

pkagrawal · 2020-12-29T22:57:14Z

@iwankgb Thanks for taking a look again and pointing me to a test case. I've now added your test case as well.

iwankgb · 2020-12-30T01:27:19Z

LGTM

bobbypage · 2020-12-30T08:59:37Z

LGTM, thanks.

Fix race between OnDemandHousekeeping and housekeepingTick

2aad4d6

This fixes the data race between the functions which could be running in different goroutines. Signed-off-by: Pradyumna Agrawal <pradyumnaa@vmware.com>

google-cla bot added the cla: yes label Dec 7, 2020

k8s-ci-robot added the needs-ok-to-test label Dec 7, 2020

pkagrawal added 2 commits December 7, 2020 10:15

Fix typo in previous commit

8ab9356

Signed-off-by: Pradyumna Agrawal <pradyumnaa@vmware.com>

cd.clock.Since(statsLastUpdatedTime) -> cd.clock.Since(cd.statsLastUp…

fe157a0

…datedTime) Signed-off-by: Pradyumna Agrawal <pradyumnaa@vmware.com>

k8s-ci-robot added ok-to-test and removed needs-ok-to-test labels Dec 7, 2020

iwankgb reviewed Dec 7, 2020

View reviewed changes

add a test case

409ce2c

Signed-off-by: Pradyumna Agrawal <pradyumnaa@vmware.com>

bobbypage approved these changes Dec 30, 2020

View reviewed changes

bobbypage merged commit ab76769 into google:master Dec 30, 2020

This was referenced Mar 1, 2021

Backporting #2750, 2755 and #2770 to 0.37 #2816

Closed

Backporting #2750, #2755 and #2770 to 0.38 #2815

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix race between `OnDemandHousekeeping` and `housekeepingTick` #2755

Fix race between `OnDemandHousekeeping` and `housekeepingTick` #2755

pkagrawal commented Dec 7, 2020 •

edited

Loading

k8s-ci-robot commented Dec 7, 2020

pkagrawal commented Dec 7, 2020

iwankgb commented Dec 7, 2020

iwankgb Dec 7, 2020

pkagrawal Dec 7, 2020

iwankgb Dec 7, 2020

pkagrawal Dec 8, 2020

pkagrawal Dec 9, 2020

iwankgb Dec 9, 2020

iwankgb commented Dec 12, 2020

iwankgb commented Dec 29, 2020

iwankgb commented Dec 29, 2020

iwankgb commented Dec 29, 2020

iwankgb commented Dec 29, 2020

pkagrawal commented Dec 29, 2020 •

edited

Loading

iwankgb commented Dec 30, 2020

bobbypage commented Dec 30, 2020

Fix race between OnDemandHousekeeping and housekeepingTick #2755

Fix race between OnDemandHousekeeping and housekeepingTick #2755

Conversation

pkagrawal commented Dec 7, 2020 • edited Loading

k8s-ci-robot commented Dec 7, 2020

pkagrawal commented Dec 7, 2020

iwankgb commented Dec 7, 2020

iwankgb Dec 7, 2020

Choose a reason for hiding this comment

pkagrawal Dec 7, 2020

Choose a reason for hiding this comment

iwankgb Dec 7, 2020

Choose a reason for hiding this comment

pkagrawal Dec 8, 2020

Choose a reason for hiding this comment

pkagrawal Dec 9, 2020

Choose a reason for hiding this comment

iwankgb Dec 9, 2020

Choose a reason for hiding this comment

iwankgb commented Dec 12, 2020

iwankgb commented Dec 29, 2020

iwankgb commented Dec 29, 2020

iwankgb commented Dec 29, 2020

iwankgb commented Dec 29, 2020

pkagrawal commented Dec 29, 2020 • edited Loading

iwankgb commented Dec 30, 2020

bobbypage commented Dec 30, 2020

Fix race between `OnDemandHousekeeping` and `housekeepingTick` #2755

Fix race between `OnDemandHousekeeping` and `housekeepingTick` #2755

pkagrawal commented Dec 7, 2020 •

edited

Loading

pkagrawal commented Dec 29, 2020 •

edited

Loading