runtime: fix tracing of syscall exit

Fix tracing of syscall exit after:
https://go-review.googlesource.com/#/c/7504/

Change-Id: Idcde2aa826d2b9a05d0a90a80242b6bfa78846ab
Reviewed-on: https://go-review.googlesource.com/8728
Reviewed-by: Rick Hudson <rlh@golang.org>
Run-TryBot: Dmitry Vyukov <dvyukov@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>

2 files changed, 23 insertions, 10 deletions

diff --git a/src/runtime/proc1.go b/src/runtime/proc1.go
index b2ab04d464..3b09149260 100644
--- a/src/runtime/proc1.go
+++ b/src/runtime/proc1.go
@@ -1813,17 +1813,18 @@ func exitsyscall(dummy int32) {
 		return
 	}
 
+	var exitTicks int64
 	if trace.enabled {
 		// Wait till traceGoSysBlock event is emited.
 		// This ensures consistency of the trace (the goroutine is started after it is blocked).
 		for oldp != nil && oldp.syscalltick == _g_.m.syscalltick {
 			osyield()
 		}
-		// This can't be done since the GC may be running and this code
-		// will invoke write barriers.
-		// TODO: Figure out how to get traceGoSysExit into the trace log or
-		// it is likely not to work as expected.
-		//		systemstack(traceGoSysExit)
+		// We can't trace syscall exit right now because we don't have a P.
+		// Tracing code can invoke write barriers that cannot run without a P.
+		// So instead we remember the syscall exit time and emit the event
+		// below when we have a P.
+		exitTicks = cputicks()
 	}
 
 	_g_.m.locks--
@@ -1831,6 +1832,11 @@ func exitsyscall(dummy int32) {
 	// Call the scheduler.
 	mcall(exitsyscall0)
 
+	// The goroutine must not be re-scheduled up to traceGoSysExit.
+	// Otherwise we can emit GoStart but not GoSysExit, that would lead
+	// no an inconsistent trace.
+	_g_.m.locks++
+
 	if _g_.m.mcache == nil {
 		throw("lost mcache")
 	}
@@ -1844,6 +1850,13 @@ func exitsyscall(dummy int32) {
 	_g_.syscallsp = 0
 	_g_.m.p.syscalltick++
 	_g_.throwsplit = false
+
+	if exitTicks != 0 {
+		systemstack(func() {
+			traceGoSysExit(exitTicks)
+		})
+	}
+	_g_.m.locks--
 }
 
 //go:nosplit
@@ -1871,7 +1884,7 @@ func exitsyscallfast() bool {
 					// Denote blocking of the new syscall.
 					traceGoSysBlock(_g_.m.p)
 					// Denote completion of the current syscall.
-					traceGoSysExit()
+					traceGoSysExit(0)
 				})
 			}
 			_g_.m.p.syscalltick++
@@ -1895,7 +1908,7 @@ func exitsyscallfast() bool {
 						osyield()
 					}
 				}
-				traceGoSysExit()
+				traceGoSysExit(0)
 			}
 		})
 		if ok {
diff --git a/src/runtime/trace.go b/src/runtime/trace.go
index 5146850770..a149799527 100644
--- a/src/runtime/trace.go
+++ b/src/runtime/trace.go
@@ -45,7 +45,7 @@ const (
 	traceEvGoBlockCond    = 26 // goroutine blocks on Cond [timestamp, stack]
 	traceEvGoBlockNet     = 27 // goroutine blocks on network [timestamp, stack]
 	traceEvGoSysCall      = 28 // syscall enter [timestamp, stack]
-	traceEvGoSysExit      = 29 // syscall exit [timestamp, goroutine id]
+	traceEvGoSysExit      = 29 // syscall exit [timestamp, goroutine id, real timestamp]
 	traceEvGoSysBlock     = 30 // syscall blocks [timestamp]
 	traceEvGoWaiting      = 31 // denotes that goroutine is blocked when tracing starts [goroutine id]
 	traceEvGoInSyscall    = 32 // denotes that goroutine is in syscall when tracing starts [goroutine id]
@@ -797,8 +797,8 @@ func traceGoSysCall() {
 	traceEvent(traceEvGoSysCall, 4)
 }
 
-func traceGoSysExit() {
-	traceEvent(traceEvGoSysExit, -1, uint64(getg().m.curg.goid))
+func traceGoSysExit(ts int64) {
+	traceEvent(traceEvGoSysExit, -1, uint64(getg().m.curg.goid), uint64(ts)/traceTickDiv)
 }
 
 func traceGoSysBlock(pp *p) {