runtime: remove overlap in the GC CPU pause time metrics

Currently the GC CPU pause time metrics start measuring before the STW
is complete. This results in a slightly less accurate measurement and
creates some overlap with other timings (for example, the idle time of
idle Ps) that will cause double-counting.

This CL adds a field to worldStop to track the point at which the world
actually stopped and uses that as the basis for the GC CPU pause time
metrics, basically eliminating this overlap.

Note that this will cause Ps in _Pgcstop before the world is fully
stopped to be counted as user time. A follow-up CL will fix this
discrepancy.

Change-Id: I287731f08415ffd97d327f582ddf7e5d2248a6f5
Reviewed-on: https://go-review.googlesource.com/c/go/+/570258
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
Auto-Submit: Michael Knyszek <mknyszek@google.com>
Reviewed-by: Nicolas Hillegeer <aktau@google.com>

diff --git a/src/runtime/mgc.go b/src/runtime/mgc.go
index 4ea55eceb6f5ada9b7230a4a07ebdab93f4d03b0..55ae765657fba83481328592f344dcfe875cb9ab 100644 (file)
--- a/src/runtime/mgc.go
+++ b/src/runtime/mgc.go
@@ -749,12 +749,12 @@ func gcStart(trigger gcTrigger) {
        // Use maxprocs instead of stwprocs here because the total time
        // computed in the CPU stats is based on maxprocs, and we want them
        // to be comparable.
-       work.cpuStats.accumulateGCPauseTime(nanotime()-work.tSweepTerm, work.maxprocs)
+       work.cpuStats.accumulateGCPauseTime(nanotime()-stw.finishedStopping, work.maxprocs)
 
        // Concurrent mark.
        systemstack(func() {
                now = startTheWorldWithSema(0, stw)
-               work.pauseNS += now - stw.start
+               work.pauseNS += now - stw.startedStopping
                work.tMark = now
 
                // Release the CPU limiter.
@@ -895,7 +895,7 @@ top:
                getg().m.preemptoff = ""
                systemstack(func() {
                        now := startTheWorldWithSema(0, stw)
-                       work.pauseNS += now - stw.start
+                       work.pauseNS += now - stw.startedStopping
                })
                semrelease(&worldsema)
                goto top
@@ -1015,7 +1015,7 @@ func gcMarkTermination(stw worldStop) {
        now := nanotime()
        sec, nsec, _ := time_now()
        unixNow := sec*1e9 + int64(nsec)
-       work.pauseNS += now - stw.start
+       work.pauseNS += now - stw.startedStopping
        work.tEnd = now
        atomic.Store64(&memstats.last_gc_unix, uint64(unixNow)) // must be Unix time to make sense to user
        atomic.Store64(&memstats.last_gc_nanotime, uint64(now)) // monotonic time for us
@@ -1031,7 +1031,7 @@ func gcMarkTermination(stw worldStop) {
        //
        // Pass gcMarkPhase=true to accumulate so we can get all the latest GC CPU stats
        // in there too.
-       work.cpuStats.accumulateGCPauseTime(work.tEnd-work.tMarkTerm, work.maxprocs)
+       work.cpuStats.accumulateGCPauseTime(now-stw.finishedStopping, work.maxprocs)
        work.cpuStats.accumulate(now, true)
 
        // Compute overall GC CPU utilization.

diff --git a/src/runtime/proc.go b/src/runtime/proc.go
index a6813169c757469cfd8837ec1f21a02dd0a66fde..1aad8e3c63157717eea38c8e5861ba3cd4cecf93 100644 (file)
--- a/src/runtime/proc.go
+++ b/src/runtime/proc.go
@@ -1322,8 +1322,9 @@ var stwReasonStrings = [...]string{
 // worldStop provides context from the stop-the-world required by the
 // start-the-world.
 type worldStop struct {
-       reason stwReason
-       start  int64
+       reason           stwReason
+       startedStopping  int64
+       finishedStopping int64
 }
 
 // Temporary variable for stopTheWorld, when it can't write to the stack.
@@ -1522,7 +1523,8 @@ func stopTheWorldWithSema(reason stwReason) worldStop {
                }
        }
 
-       startTime := nanotime() - start
+       finish := nanotime()
+       startTime := finish - start
        if reason.isGC() {
                sched.stwStoppingTimeGC.record(startTime)
        } else {
@@ -1554,7 +1556,7 @@ func stopTheWorldWithSema(reason stwReason) worldStop {
 
        worldStopped()
 
-       return worldStop{reason: reason, start: start}
+       return worldStop{reason: reason, startedStopping: start, finishedStopping: finish}
 }
 
 // reason is the same STW reason passed to stopTheWorld. start is the start
@@ -1610,7 +1612,7 @@ func startTheWorldWithSema(now int64, w worldStop) int64 {
        if now == 0 {
                now = nanotime()
        }
-       totalTime := now - w.start
+       totalTime := now - w.startedStopping
        if w.reason.isGC() {
                sched.stwTotalTimeGC.record(totalTime)
        } else {