runtime: fix race that dropped GoSysExit events from trace

This makes TestTraceStressStartStop much less flaky.
Running under stress, it changes the failure rate from
above 1/100 to under 1/50000. That very unlikely
failure happens when an unexpected GoSysExit is
written. Not sure how that happens yet, but it is much
less important.

Fixes #11953.

Change-Id: I034671936334b4f3ab733614ef239aa121d20247
Reviewed-on: https://go-review.googlesource.com/13321
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>

1 files changed, 17 insertions, 1 deletions

diff --git a/src/runtime/proc1.go b/src/runtime/proc1.go
index 23beaf537c..09cb775f0d 100644
--- a/src/runtime/proc1.go
+++ b/src/runtime/proc1.go
@@ -1348,7 +1348,23 @@ func execute(gp *g, inheritTime bool) {
 		// GoSysExit has to happen when we have a P, but before GoStart.
 		// So we emit it here.
 		if gp.syscallsp != 0 && gp.sysblocktraced {
-			traceGoSysExit(gp.sysexitseq, gp.sysexitticks)
+			// Since gp.sysblocktraced is true, we must emit an event.
+			// There is a race between the code that initializes sysexitseq
+			// and sysexitticks (in exitsyscall, which runs without a P,
+			// and therefore is not stopped with the rest of the world)
+			// and the code that initializes a new trace.
+			// The recorded sysexitseq and sysexitticks must therefore
+			// be treated as "best effort". If they are valid for this trace,
+			// then great, use them for greater accuracy.
+			// But if they're not valid for this trace, assume that the
+			// trace was started after the actual syscall exit (but before
+			// we actually managed to start the goroutine, aka right now),
+			// and assign a fresh time stamp to keep the log consistent.
+			seq, ts := gp.sysexitseq, gp.sysexitticks
+			if seq == 0 || int64(seq)-int64(trace.seqStart) < 0 {
+				seq, ts = tracestamp()
+			}
+			traceGoSysExit(seq, ts)
 		}
 		traceGoStart()
 	}