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>

diff --git a/src/runtime/malloc_test.go b/src/runtime/malloc_test.go
index ecef9c93bc422baa7a8869f4d7c7f3be18fccecb..f0e73baea59385a6eea1536eeb052aff31b36a13 100644 (file)
--- a/src/runtime/malloc_test.go
+++ b/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) {

diff --git a/src/runtime/mgc.go b/src/runtime/mgc.go
index 8375d30bb8056b8cca150f36deaa9fd721617139..4eff8fc59b6ab3510f03e073214107e4ad34bf4c 100644 (file)
--- a/src/runtime/mgc.go
+++ b/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) {