runtime: make STW duration more accurate

Currently, GC captures the start-the-world time stamp after
startTheWorldWithSema returns. This is problematic for two reasons:

1. It's possible to get preempted between startTheWorldWithSema
starting the world and calling nanotime.

2. startTheWorldWithSema does several clean-up tasks after the world
is up and running that on rare occasions can take upwards of 10ms.

Since the runtime uses the start-the-world time stamp to compute the
STW duration, both of these can significantly inflate the reported STW
duration.

Fix this by having startTheWorldWithSema itself call nanotime once the
world is started.

Change-Id: I114630234fb73c9dabae50a2ef1884661f2459db
Reviewed-on: https://go-review.googlesource.com/55410
Run-TryBot: Austin Clements <austin@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Rick Hudson <rlh@golang.org>

diff --git a/src/runtime/mgc.go b/src/runtime/mgc.go
index 111fa781e1ddef67d5875123970e6554ca6c9cb5..0e57d960c402b2d7239850461fbf13ade360fd83 100644 (file)
--- a/src/runtime/mgc.go
+++ b/src/runtime/mgc.go
@@ -1308,8 +1308,9 @@ func gcStart(mode gcMode, trigger gcTrigger) {
                gcController.markStartTime = now
 
                // Concurrent mark.
-               systemstack(startTheWorldWithSema)
-               now = nanotime()
+               systemstack(func() {
+                       now = startTheWorldWithSema()
+               })
                work.pauseNS += now - work.pauseStart
                work.tMark = now
        } else {
@@ -1573,7 +1574,7 @@ func gcMarkTermination(nextTriggerRatio float64) {
        // so events don't leak into the wrong cycle.
        mProf_NextCycle()
 
-       systemstack(startTheWorldWithSema)
+       systemstack(func() { startTheWorldWithSema() })
 
        // Flush the heap profile so we can start a new cycle next GC.
        // This is relatively expensive, so we don't do it with the

diff --git a/src/runtime/proc.go b/src/runtime/proc.go
index ed333bb92eeeb915f4b376c56dd608ebb1cdd896..cc1e30a925a25cd2ca7c1b9170eaff7179d45fb3 100644 (file)
--- a/src/runtime/proc.go
+++ b/src/runtime/proc.go
@@ -941,7 +941,7 @@ func stopTheWorld(reason string) {
 
 // startTheWorld undoes the effects of stopTheWorld.
 func startTheWorld() {
-       systemstack(startTheWorldWithSema)
+       systemstack(func() { startTheWorldWithSema() })
        // worldsema must be held over startTheWorldWithSema to ensure
        // gomaxprocs cannot change while worldsema is held.
        semrelease(&worldsema)
@@ -1057,7 +1057,7 @@ func mhelpgc() {
        _g_.m.helpgc = -1
 }
 
-func startTheWorldWithSema() {
+func startTheWorldWithSema() int64 {
        _g_ := getg()
 
        _g_.m.locks++        // disable preemption because it can be holding p in a local var
@@ -1097,6 +1097,9 @@ func startTheWorldWithSema() {
                }
        }
 
+       // Capture start-the-world time before doing clean-up tasks.
+       startTime := nanotime()
+
        // Wakeup an additional proc in case we have excessive runnable goroutines
        // in local queues or in the global queue. If we don't, the proc will park itself.
        // If we have lots of excessive work, resetspinning will unpark additional procs as necessary.
@@ -1118,6 +1121,8 @@ func startTheWorldWithSema() {
        if _g_.m.locks == 0 && _g_.preempt { // restore the preemption request in case we've cleared it in newstack
                _g_.stackguard0 = stackPreempt
        }
+
+       return startTime
 }
 
 // Called to start an M.