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 <[email protected]>
TryBot-Result: Gobot Gobot <[email protected]>
Reviewed-by: Austin Clements <[email protected]>

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)
+	}
+}

src/runtime/proc.go

@@ -2767,14 +2767,17 @@ 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()
 	mcall(goyield_m)
 }
 
 func goyield_m(gp *g) {
+	if trace.enabled {
+		traceGoPreempt()
+	}
 	pp := gp.m.p.ptr()
 	casgstatus(gp, _Grunning, _Grunnable)
 	dropg()

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,