From a4c579e8f7c8129b2c27779f206ebd2c9b393633 Mon Sep 17 00:00:00 2001 From: Rhys Hiltner Date: Tue, 17 Dec 2019 16:40:46 -0800 Subject: [PATCH] runtime: emit trace event in direct semaphore handoff When a goroutine yields the remainder of its time to another goroutine during direct semaphore handoff (as in an Unlock of a sync.Mutex in starvation mode), it needs to signal that change to the execution tracer. The discussion in CL 200577 didn't reach consensus on how best to describe that, but pointed out that "traceEvGoSched / goroutine calls Gosched" could be confusing. Emit a "traceEvGoPreempt / goroutine is preempted" event in this case, to allow the execution tracer to find a consistent event ordering without being both specific and inaccurate about why the active goroutine has changed. Fixes #36186 Change-Id: Ic4ade19325126db2599aff6aba7cba028bb0bee9 Reviewed-on: https://go-review.googlesource.com/c/go/+/211797 Run-TryBot: Dan Scales TryBot-Result: Gobot Gobot Reviewed-by: Austin Clements --- src/cmd/trace/trace_test.go | 33 +++++++++++++++++++++++++++++++++ src/runtime/proc.go | 5 ++++- src/runtime/sema.go | 6 +++--- 3 files changed, 40 insertions(+), 4 deletions(-) diff --git a/src/cmd/trace/trace_test.go b/src/cmd/trace/trace_test.go index 9e90f50d4ba912..ef2d06c961a498 100644 --- a/src/cmd/trace/trace_test.go +++ b/src/cmd/trace/trace_test.go @@ -12,7 +12,9 @@ import ( "io/ioutil" rtrace "runtime/trace" "strings" + "sync" "testing" + "time" ) // stacks is a fake stack map populated for test. @@ -233,3 +235,34 @@ func TestFoo(t *testing.T) { } } + +func TestDirectSemaphoreHandoff(t *testing.T) { + prog0 := func() { + var mu sync.Mutex + var wg sync.WaitGroup + mu.Lock() + // This is modeled after src/sync/mutex_test.go to trigger Mutex + // starvation mode, in which the goroutine that calls Unlock hands off + // both the semaphore and its remaining time slice. See issue 36186. + for i := 0; i < 2; i++ { + wg.Add(1) + go func() { + defer wg.Done() + for i := 0; i < 100; i++ { + mu.Lock() + time.Sleep(100 * time.Microsecond) + mu.Unlock() + } + }() + } + mu.Unlock() + wg.Wait() + } + if err := traceProgram(t, prog0, "TestDirectSemaphoreHandoff"); err != nil { + t.Fatalf("failed to trace the program: %v", err) + } + _, err := parseTrace() + if err != nil { + t.Fatalf("failed to parse the trace: %v", err) + } +} diff --git a/src/runtime/proc.go b/src/runtime/proc.go index d264e1d1208d4d..26af68e3c11470 100644 --- a/src/runtime/proc.go +++ b/src/runtime/proc.go @@ -2767,7 +2767,7 @@ func preemptPark(gp *g) { } // goyield is like Gosched, but it: -// - does not emit a GoSched trace event +// - emits a GoPreempt trace event instead of a GoSched trace event // - puts the current G on the runq of the current P instead of the globrunq func goyield() { checkTimeouts() @@ -2775,6 +2775,9 @@ func goyield() { } func goyield_m(gp *g) { + if trace.enabled { + traceGoPreempt() + } pp := gp.m.p.ptr() casgstatus(gp, _Grunning, _Grunnable) dropg() diff --git a/src/runtime/sema.go b/src/runtime/sema.go index 7bbf871caa434b..9bfd4f96d5872c 100644 --- a/src/runtime/sema.go +++ b/src/runtime/sema.go @@ -199,9 +199,9 @@ func semrelease1(addr *uint32, handoff bool, skipframes int) { // the waiter G immediately. // Note that waiter inherits our time slice: this is desirable // to avoid having a highly contended semaphore hog the P - // indefinitely. goyield is like Gosched, but it does not emit a - // GoSched trace event and, more importantly, puts the current G - // on the local runq instead of the global one. + // indefinitely. goyield is like Gosched, but it emits a + // "preempted" trace event instead and, more importantly, puts + // the current G on the local runq instead of the global one. // We only do this in the starving regime (handoff=true), as in // the non-starving case it is possible for a different waiter // to acquire the semaphore while we are yielding/scheduling,