From 777ab5ce1a47bc7cc71e6a675c2dcc76e69e11d5 Mon Sep 17 00:00:00 2001 From: Austin Clements Date: Wed, 1 Jul 2015 11:04:19 -0400 Subject: [PATCH] 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 --- src/runtime/malloc_test.go | 17 ++++++++++++++- src/runtime/mgc.go | 42 +++++++++++++++++++++++--------------- 2 files changed, 42 insertions(+), 17 deletions(-) diff --git a/src/runtime/malloc_test.go b/src/runtime/malloc_test.go index ecef9c93bc..f0e73baea5 100644 --- 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 8375d30bb8..4eff8fc59b 100644 --- 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) { -- 2.48.1