]> Cypherpunks repositories - gostls13.git/commitdiff
runtime: update gctrace line for new garbage collector
authorAustin Clements <austin@google.com>
Thu, 26 Mar 2015 22:48:42 +0000 (18:48 -0400)
committerAustin Clements <austin@google.com>
Thu, 2 Apr 2015 23:37:06 +0000 (23:37 +0000)
GODEBUG=gctrace=1 turns on a per-GC cycle trace line. The current line
is left over from the STW garbage collector and includes a lot of
information that is no longer meaningful for the concurrent GC and
doesn't include a lot of information that is important.

Replace this line with a new line designed for the new garbage
collector.

This new line is focused more on helping the user understand the
impact of the garbage collector on their program and less on telling
us, the runtime developers, everything that's happening inside
GC. It's designed to fit in 80 columns and intentionally omit some
potentially useful things that were in the old line. We might want a
"verbose" mode that adds information for us.

We'll be able to further simplify the line once we eliminate the STW
around enabling the write barrier. Then we'll have just one STW phase,
one concurrent phase, and one more STW phase, so we'll be able to
reduce the number of times from five to three.

Change-Id: Icc30939fe4576fb4491b4eac811649395727aa2a
Reviewed-on: https://go-review.googlesource.com/8208
Reviewed-by: Russ Cox <rsc@golang.org>
src/runtime/mgc.go
src/runtime/proc.go

index 89f3fb534086d98e2f78519d25387a15219af8c9..057f8974158fcdf3a4a27f549e1d33f7d74c7372 100644 (file)
@@ -282,6 +282,11 @@ func backgroundgc() {
 }
 
 func gc(mode int) {
+       // debug.gctrace variables
+       var stwprocs, maxprocs int32
+       var tSweepTerm, tScan, tInstallWB, tMark, tMarkTerm int64
+       var heap0, heap1 uint64
+
        // Ok, we're doing it!  Stop everybody else
        semacquire(&worldsema, false)
 
@@ -297,6 +302,11 @@ func gc(mode int) {
        if mode == gcBackgroundMode {
                gctimer.cycle.sweepterm = nanotime()
        }
+       if debug.gctrace > 0 {
+               stwprocs, maxprocs = gcprocs(), gomaxprocs
+               tSweepTerm = nanotime()
+               heap0 = memstats.heap_alloc
+       }
 
        if trace.enabled {
                traceGoSched()
@@ -316,10 +326,16 @@ func gc(mode int) {
                        // Concurrent scan.
                        starttheworld()
                        gctimer.cycle.scan = nanotime()
+                       if debug.gctrace > 0 {
+                               tScan = nanotime()
+                       }
                        gcscan_m()
                        gctimer.cycle.installmarkwb = nanotime()
 
                        // Enter mark phase and enable write barriers.
+                       if debug.gctrace > 0 {
+                               tInstallWB = nanotime()
+                       }
                        stoptheworld()
                        gcphase = _GCmark
 
@@ -327,6 +343,9 @@ func gc(mode int) {
                        starttheworld()
                })
                gctimer.cycle.mark = nanotime()
+               if debug.gctrace > 0 {
+                       tMark = nanotime()
+               }
                var gcw gcWork
                gcDrain(&gcw)
                gcw.dispose()
@@ -339,6 +358,9 @@ func gc(mode int) {
 
                // Begin mark termination.
                gctimer.cycle.markterm = nanotime()
+               if debug.gctrace > 0 {
+                       tMarkTerm = nanotime()
+               }
                systemstack(stoptheworld)
                // The gcphase is _GCmark, it will transition to _GCmarktermination
                // below. The important thing is that the wb remains active until
@@ -348,12 +370,21 @@ func gc(mode int) {
                // The g stacks have not been scanned so clear g state
                // such that mark termination scans all stacks.
                gcResetGState()
+
+               if debug.gctrace > 0 {
+                       t := nanotime()
+                       tScan, tInstallWB, tMark, tMarkTerm = t, t, t, t
+               }
        }
 
        // World is stopped.
        // Start marktermination which includes enabling the write barrier.
        gcphase = _GCmarktermination
 
+       if debug.gctrace > 0 {
+               heap1 = memstats.heap_alloc
+       }
+
        startTime := nanotime()
        if mp != acquirem() {
                throw("gcwork: rescheduled")
@@ -437,6 +468,36 @@ func gc(mode int) {
        releasem(mp)
        mp = nil
 
+       memstats.numgc++
+       if debug.gctrace > 0 {
+               // TODO(austin): Cumulative utilization %
+               // TODO(austin): Marked heap size at end
+               tEnd := nanotime()
+               var sbuf [24]byte
+               printlock()
+               print("gc #", memstats.numgc,
+                       " @", string(itoaDiv(sbuf[:], uint64(tEnd-runtimeInitTime)/1e6, 3)), "s: ",
+                       (tScan-tSweepTerm)/1e6,
+                       "+", (tInstallWB-tScan)/1e6,
+                       "+", (tMark-tInstallWB)/1e6,
+                       "+", (tMarkTerm-tMark)/1e6,
+                       "+", (tEnd-tMarkTerm)/1e6, " ms clock, ",
+                       int64(stwprocs)*(tScan-tSweepTerm)/1e6,
+                       "+", (tInstallWB-tScan)/1e6,
+                       "+", int64(stwprocs)*(tMark-tInstallWB)/1e6,
+                       "+", (tMarkTerm-tMark)/1e6, "+",
+                       int64(stwprocs)*(tEnd-tMarkTerm)/1e6, " ms cpu, ",
+                       heap0>>20, "->", heap1>>20, " MB, ",
+                       maxprocs, " P")
+               if mode != gcBackgroundMode {
+                       print(" (forced)")
+               }
+               print("\n")
+               printunlock()
+       }
+       sweep.nbgsweep = 0
+       sweep.npausesweep = 0
+
        // now that gc is done, kick off finalizer thread if needed
        if !concurrentSweep {
                // give the queued finalizers, if any, a chance to run
@@ -457,10 +518,6 @@ func gcMark(start_time int64) {
        }
        t0 := start_time
        work.tstart = start_time
-       var t1 int64
-       if debug.gctrace > 0 {
-               t1 = nanotime()
-       }
 
        gcCopySpans() // TODO(rlh): should this be hoisted and done only once? Right now it is done for normal marking and also for checkmarking.
 
@@ -478,11 +535,6 @@ func gcMark(start_time int64) {
                helpgc(int32(work.nproc))
        }
 
-       var t2 int64
-       if debug.gctrace > 0 {
-               t2 = nanotime()
-       }
-
        harvestwbufs() // move local workbufs onto global queues where the GC can find them
        gchelperstart()
        parfordo(work.markfor)
@@ -497,11 +549,6 @@ func gcMark(start_time int64) {
                throw("work.partial != 0")
        }
 
-       var t3 int64
-       if debug.gctrace > 0 {
-               t3 = nanotime()
-       }
-
        if work.nproc > 1 {
                notesleep(&work.alldone)
        }
@@ -514,8 +561,6 @@ func gcMark(start_time int64) {
 
        cachestats()
        // next_gc calculation is tricky with concurrent sweep since we don't know size of live heap
-       // estimate what was live heap size after previous GC (for printing only)
-       heap0 := memstats.next_gc * 100 / (uint64(gcpercent) + 100)
        // conservatively set next_gc to high value assuming that everything is live
        // concurrent/lazy sweep will reduce this number while discovering new garbage
        memstats.next_gc = memstats.heap_alloc + memstats.heap_alloc*uint64(gcpercent)/100
@@ -532,37 +577,6 @@ func gcMark(start_time int64) {
        memstats.pause_ns[memstats.numgc%uint32(len(memstats.pause_ns))] = uint64(t4 - t0)
        memstats.pause_end[memstats.numgc%uint32(len(memstats.pause_end))] = uint64(t4)
        memstats.pause_total_ns += uint64(t4 - t0)
-       memstats.numgc++
-       if memstats.debuggc {
-               print("pause ", t4-t0, "\n")
-       }
-
-       if debug.gctrace > 0 {
-               heap1 := memstats.heap_alloc
-               var stats gcstats
-               updatememstats(&stats)
-               if heap1 != memstats.heap_alloc {
-                       print("runtime: mstats skew: heap=", heap1, "/", memstats.heap_alloc, "\n")
-                       throw("mstats skew")
-               }
-               obj := memstats.nmalloc - memstats.nfree
-
-               stats.nprocyield += work.markfor.nprocyield
-               stats.nosyield += work.markfor.nosyield
-               stats.nsleep += work.markfor.nsleep
-
-               print("gc", memstats.numgc, "(", work.nproc, "): ",
-                       (t1-t0)/1000, "+", (t2-t1)/1000, "+", (t3-t2)/1000, "+", (t4-t3)/1000, " us, ",
-                       heap0>>20, " -> ", heap1>>20, " MB, ",
-                       obj, " (", memstats.nmalloc, "-", memstats.nfree, ") objects, ",
-                       gcount(), " goroutines, ",
-                       len(work.spans), "/", sweep.nbgsweep, "/", sweep.npausesweep, " sweeps, ",
-                       stats.nhandoff, "(", stats.nhandoffcnt, ") handoff, ",
-                       work.markfor.nsteal, "(", work.markfor.nstealcnt, ") steal, ",
-                       stats.nprocyield, "/", stats.nosyield, "/", stats.nsleep, " yields\n")
-               sweep.nbgsweep = 0
-               sweep.npausesweep = 0
-       }
 }
 
 func gcSweep(mode int) {
@@ -833,3 +847,20 @@ func GCprinttimes() {
        printPhase("mark term: ", func(t *gctimes) int64 { return t.markterm }, gomaxprocs)
        printunlock()
 }
+
+// itoaDiv formats val/(10**dec) into buf.
+func itoaDiv(buf []byte, val uint64, dec int) []byte {
+       i := len(buf) - 1
+       idec := i - dec
+       for val >= 10 || i >= idec {
+               buf[i] = byte(val%10 + '0')
+               i--
+               if i == idec {
+                       buf[i] = '.'
+                       i--
+               }
+               val /= 10
+       }
+       buf[i] = byte(val + '0')
+       return buf[i:]
+}
index edab9bfdd62e32cfb18c6ac8ab0aa6b024dc158e..968d5e925b278e17396be31f8628def65a59dcce 100644 (file)
@@ -15,6 +15,9 @@ func main_init()
 //go:linkname main_main main.main
 func main_main()
 
+// runtimeInitTime is the nanotime() at which the runtime started.
+var runtimeInitTime int64
+
 // The main goroutine.
 func main() {
        g := getg()
@@ -32,6 +35,9 @@ func main() {
                maxstacksize = 250000000
        }
 
+       // Record when the world started.
+       runtimeInitTime = nanotime()
+
        systemstack(func() {
                newm(sysmon, nil)
        })