runtime: fix MemStats.{PauseNS,PauseEnd,PauseTotalNS,LastGC}

These memstats are currently being computed by gcMark, which was
appropriate in Go 1.4, but gcMark is now just one part of a bigger
picture. In particular, it can't account for the sweep termination
pause time, it can't account for all of the mark termination pause
time, and the reported "pause end" and "last GC" times will be
slightly earlier than they really are.

Lift computing of these statistics into func gc, which has the
appropriate visibility into the process to compute them correctly.

Fixes one of the issues in #10323. This does not add new statistics
appropriate to the concurrent collector; it simply fixes existing
statistics that are being misreported.

Change-Id: I670cb16594a8641f6b27acf4472db15b6e8e086e
Reviewed-on: https://go-review.googlesource.com/11794
Reviewed-by: Russ Cox <rsc@golang.org>

src/runtime/malloc_test.go

@@ -32,7 +32,7 @@ func TestMemStats(t *testing.T) {
 		st.HeapIdle > 1e10 || st.HeapInuse > 1e10 || st.HeapObjects > 1e10 || st.StackInuse > 1e10 ||
 		st.StackSys > 1e10 || st.MSpanInuse > 1e10 || st.MSpanSys > 1e10 || st.MCacheInuse > 1e10 ||
 		st.MCacheSys > 1e10 || st.BuckHashSys > 1e10 || st.GCSys > 1e10 || st.OtherSys > 1e10 ||
-		st.NextGC > 1e10 || st.NumGC > 1e9 {
+		st.NextGC > 1e10 || st.NumGC > 1e9 || st.PauseTotalNs > 1e11 {
 		t.Fatalf("Insanely high value (overflow?): %+v", *st)
 	}
 
@@ -48,6 +48,21 @@ func TestMemStats(t *testing.T) {
 	if lpe := st.PauseEnd[int(st.NumGC+255)%len(st.PauseEnd)]; st.LastGC != lpe {
 		t.Fatalf("LastGC(%d) != last PauseEnd(%d)", st.LastGC, lpe)
 	}
+
+	var pauseTotal uint64
+	for _, pause := range st.PauseNs {
+		pauseTotal += pause
+	}
+	if int(st.NumGC) < len(st.PauseNs) {
+		// We have all pauses, so this should be exact.
+		if st.PauseTotalNs != pauseTotal {
+			t.Fatalf("PauseTotalNs(%d) != sum PauseNs(%d)", st.PauseTotalNs, pauseTotal)
+		}
+	} else {
+		if st.PauseTotalNs < pauseTotal {
+			t.Fatalf("PauseTotalNs(%d) < sum PauseNs(%d)", st.PauseTotalNs, pauseTotal)
+		}
+	}
 }
 
 func TestStringConcatenationAllocs(t *testing.T) {

src/runtime/mgc.go

@@ -855,6 +855,9 @@ func gc(mode int) {
 	var tSweepTerm, tScan, tInstallWB, tMark, tMarkTerm int64
 	var heap0, heap1, heap2, heapGoal uint64
 
+	// memstats statistics
+	var now, pauseStart, pauseNS int64
+
 	// Ok, we're doing it!  Stop everybody else
 	semacquire(&worldsema, false)
 
@@ -869,12 +872,17 @@ func gc(mode int) {
 		sweep.nbgsweep++
 	}
 
+	if trace.enabled {
+		traceGCStart()
+	}
+
 	if mode == gcBackgroundMode {
 		gcBgMarkStartWorkers()
 	}
+	now = nanotime()
 	if debug.gctrace > 0 {
 		stwprocs, maxprocs = gcprocs(), gomaxprocs
-		tSweepTerm = nanotime()
+		tSweepTerm = now
 		if mode == gcBackgroundMode {
 			// We started GC when heap_live == next_gc,
 			// but the mutator may have allocated between
@@ -885,10 +893,7 @@ func gc(mode int) {
 		}
 	}
 
-	if trace.enabled {
-		traceGCStart()
-	}
-
+	pauseStart = now
 	systemstack(stopTheWorldWithSema)
 	systemstack(finishsweep_m) // finish sweep before we start concurrent scan.
 	// clearpools before we start the GC. If we wait they memory will not be
@@ -931,8 +936,10 @@ func gc(mode int) {
 
 			// Concurrent scan.
 			startTheWorldWithSema()
+			now = nanotime()
+			pauseNS += now - pauseStart
 			if debug.gctrace > 0 {
-				tScan = nanotime()
+				tScan = now
 			}
 			gcscan_m()
 
@@ -985,9 +992,11 @@ func gc(mode int) {
 		}
 
 		// Begin mark termination.
+		now = nanotime()
 		if debug.gctrace > 0 {
-			tMarkTerm = nanotime()
+			tMarkTerm = now
 		}
+		pauseStart = now
 		systemstack(stopTheWorldWithSema)
 		// The gcphase is _GCmark, it will transition to _GCmarktermination
 		// below. The important thing is that the wb remains active until
@@ -1090,13 +1099,22 @@ func gc(mode int) {
 		throw("gc done but gcphase != _GCoff")
 	}
 
+	// Update timing memstats
+	now, unixNow := nanotime(), unixnanotime()
+	pauseNS += now - pauseStart
+	atomicstore64(&memstats.last_gc, uint64(unixNow)) // must be Unix time to make sense to user
+	memstats.pause_ns[memstats.numgc%uint32(len(memstats.pause_ns))] = uint64(pauseNS)
+	memstats.pause_end[memstats.numgc%uint32(len(memstats.pause_end))] = uint64(unixNow)
+	memstats.pause_total_ns += uint64(pauseNS)
+
+	memstats.numgc++
+
 	systemstack(startTheWorldWithSema)
 	semrelease(&worldsema)
 
 	releasem(mp)
 	mp = nil
 
-	memstats.numgc++
 	if debug.gctrace > 0 {
 		tEnd := nanotime()
 
@@ -1335,7 +1353,6 @@ func gcMark(start_time int64) {
 	if gcphase != _GCmarktermination {
 		throw("in gcMark expecting to see gcphase as _GCmarktermination")
 	}
-	t0 := start_time
 	work.tstart = start_time
 
 	gcCopySpans() // TODO(rlh): should this be hoisted and done only once? Right now it is done for normal marking and also for checkmarking.
@@ -1434,13 +1451,6 @@ func gcMark(start_time int64) {
 		traceHeapAlloc()
 		traceNextGC()
 	}
-
-	t4 := nanotime()
-	unixNow := unixnanotime()
-	atomicstore64(&memstats.last_gc, uint64(unixNow)) // must be Unix time to make sense to user
-	memstats.pause_ns[memstats.numgc%uint32(len(memstats.pause_ns))] = uint64(t4 - t0)
-	memstats.pause_end[memstats.numgc%uint32(len(memstats.pause_end))] = uint64(unixNow)
-	memstats.pause_total_ns += uint64(t4 - t0)
 }
 
 func gcSweep(mode int) {