From d59bd25a30bbfc96d4123517f6f7b637c910e059 Mon Sep 17 00:00:00 2001 From: Rhys Hiltner Date: Tue, 21 Nov 2023 15:31:26 -0800 Subject: [PATCH] runtime: test for contention in both semaphore paths Most contention on the runtime locks inside semaphores is observed in runtime.semrelease1, but it can also appear in runtime.semacquire1. When examining contention profiles in TestRuntimeLockMetricsAndProfile, allow call stacks that include either. For #64253 Change-Id: Id4f16af5e9a28615ab5032a3197e8df90f7e382f Reviewed-on: https://go-review.googlesource.com/c/go/+/544375 Reviewed-by: Dmitri Shuralyov Auto-Submit: Rhys Hiltner LUCI-TryBot-Result: Go LUCI Reviewed-by: Michael Knyszek --- src/runtime/metrics_test.go | 76 +++++++++++++++++++++++++------------ 1 file changed, 51 insertions(+), 25 deletions(-) diff --git a/src/runtime/metrics_test.go b/src/runtime/metrics_test.go index d28a589adc..7074abfd69 100644 --- a/src/runtime/metrics_test.go +++ b/src/runtime/metrics_test.go @@ -1018,7 +1018,7 @@ func TestRuntimeLockMetricsAndProfile(t *testing.T) { return metricGrowth, profileGrowth, p } - testcase := func(strictTiming bool, stk []string, workers int, fn func() bool) func(t *testing.T) (metricGrowth, profileGrowth float64, n, value int64) { + testcase := func(strictTiming bool, acceptStacks [][]string, workers int, fn func() bool) func(t *testing.T) (metricGrowth, profileGrowth float64, n, value int64) { return func(t *testing.T) (metricGrowth, profileGrowth float64, n, value int64) { metricGrowth, profileGrowth, p := measureDelta(t, func() { var started, stopped sync.WaitGroup @@ -1056,19 +1056,24 @@ func TestRuntimeLockMetricsAndProfile(t *testing.T) { t.Logf("lock contention growth in runtime/pprof's view (%fs)", profileGrowth) t.Logf("lock contention growth in runtime/metrics' view (%fs)", metricGrowth) - if goexperiment.StaticLockRanking { - if !slices.ContainsFunc(stk, func(s string) bool { - return s == "runtime.systemstack" || s == "runtime.mcall" || s == "runtime.mstart" - }) { - // stk is a call stack that is still on the user stack when - // it calls runtime.unlock. Add the extra function that - // we'll see, when the static lock ranking implementation of - // runtime.unlockWithRank switches to the system stack. - stk = append([]string{"runtime.unlockWithRank"}, stk...) + acceptStacks = append([][]string(nil), acceptStacks...) + for i, stk := range acceptStacks { + if goexperiment.StaticLockRanking { + if !slices.ContainsFunc(stk, func(s string) bool { + return s == "runtime.systemstack" || s == "runtime.mcall" || s == "runtime.mstart" + }) { + // stk is a call stack that is still on the user stack when + // it calls runtime.unlock. Add the extra function that + // we'll see, when the static lock ranking implementation of + // runtime.unlockWithRank switches to the system stack. + stk = append([]string{"runtime.unlockWithRank"}, stk...) + } } + acceptStacks[i] = stk } var stks [][]string + values := make([][2]int64, len(acceptStacks)) for _, s := range p.Sample { var have []string for _, loc := range s.Location { @@ -1077,18 +1082,26 @@ func TestRuntimeLockMetricsAndProfile(t *testing.T) { } } stks = append(stks, have) - if slices.Equal(have, stk) { - n += s.Value[0] - value += s.Value[1] + for i, stk := range acceptStacks { + if slices.Equal(have, stk) { + values[i][0] += s.Value[0] + values[i][1] += s.Value[1] + } } } - t.Logf("stack %v has samples totaling n=%d value=%d", stk, n, value) + for i, stk := range acceptStacks { + n += values[i][0] + value += values[i][1] + t.Logf("stack %v has samples totaling n=%d value=%d", stk, values[i][0], values[i][1]) + } if n == 0 && value == 0 { t.Logf("profile:\n%s", p) for _, have := range stks { t.Logf("have stack %v", have) } - t.Errorf("want stack %v", stk) + for _, stk := range acceptStacks { + t.Errorf("want stack %v", stk) + } } return metricGrowth, profileGrowth, n, value @@ -1140,18 +1153,18 @@ func TestRuntimeLockMetricsAndProfile(t *testing.T) { return true } - stk := []string{ + stks := [][]string{{ "runtime.unlock", "runtime_test." + name + ".func5.1", "runtime_test.(*contentionWorker).run", - } + }} t.Run("sample-1", func(t *testing.T) { old := runtime.SetMutexProfileFraction(1) defer runtime.SetMutexProfileFraction(old) needContention.Store(int64(len(mus) - 1)) - metricGrowth, profileGrowth, n, _ := testcase(true, stk, workers, fn)(t) + metricGrowth, profileGrowth, n, _ := testcase(true, stks, workers, fn)(t) if have, want := metricGrowth, delay.Seconds()*float64(len(mus)); have < want { // The test imposes a delay with usleep, verified with calls to @@ -1175,7 +1188,7 @@ func TestRuntimeLockMetricsAndProfile(t *testing.T) { defer runtime.SetMutexProfileFraction(old) needContention.Store(int64(len(mus) - 1)) - metricGrowth, profileGrowth, n, _ := testcase(true, stk, workers, fn)(t) + metricGrowth, profileGrowth, n, _ := testcase(true, stks, workers, fn)(t) // With 100 trials and profile fraction of 2, we expect to capture // 50 samples. Allow the test to pass if we get at least 20 samples; @@ -1231,11 +1244,20 @@ func TestRuntimeLockMetricsAndProfile(t *testing.T) { return true } - stk := []string{ - "runtime.unlock", - "runtime.semrelease1", - "runtime_test.TestRuntimeLockMetricsAndProfile.func6.1", - "runtime_test.(*contentionWorker).run", + stks := [][]string{ + { + "runtime.unlock", + "runtime.semrelease1", + "runtime_test.TestRuntimeLockMetricsAndProfile.func6.1", + "runtime_test.(*contentionWorker).run", + }, + { + "runtime.unlock", + "runtime.semacquire1", + "runtime.semacquire", + "runtime_test.TestRuntimeLockMetricsAndProfile.func6.1", + "runtime_test.(*contentionWorker).run", + }, } // Verify that we get call stack we expect, with anything more than zero @@ -1243,7 +1265,11 @@ func TestRuntimeLockMetricsAndProfile(t *testing.T) { // small relative to the expected overhead for us to verify its value // more directly. Leave that to the explicit lock/unlock test. - testcase(false, stk, workers, fn)(t) + testcase(false, stks, workers, fn)(t) + + if remaining := tries.Load(); remaining >= 0 { + t.Logf("finished test early (%d tries remaining)", remaining) + } }) } -- 2.48.1