runtime: improve GC times printing

This improves the printing of GC times to be both more human-friendly
and to provide enough information for the construction of MMU curves
and other statistics.  The new times look like:

GC: #8 72413852ns @143036695895725 pause=622900 maxpause=427037 goroutines=11 gomaxprocs=4
GC:     sweep term: 190584ns	   max=190584	total=275001	procs=4
GC:     scan:       260397ns	   max=260397	total=902666	procs=1
GC:     install wb: 5279ns	   max=5279	total=18642	procs=4
GC:     mark:       71530555ns	   max=71530555	total=186694660	procs=1
GC:     mark term:  427037ns	   max=427037	total=1691184	procs=4

This prints gomaxprocs and the number of procs used in each phase for
the benefit of analyzing mutator utilization during concurrent phases.
This also means the analysis doesn't have to hard-code which phases
are STW.

This prints the absolute start time only for the GC cycle.  The other
start times can be derived from the phase durations.  This declutters
the view for humans readers and doesn't pose any additional complexity
for machine readers.

This removes the confusing "cycle" terminology.  Instead, this places
the phase duration after the phase name and adds a "ns" unit, which
both makes it implicitly clear that this is the duration of that phase
and indicates the units of the times.

This adds a "GC:" prefix to all lines for easier identification.

Finally, this generally cleans up the code as well as the placement of
spaces in the output and adds print locking so the statistics blocks
are never interrupted by other prints.

Change-Id: Ifd056db83ed1b888de7dfa9a8fc5732b01ccc631
Reviewed-on: https://go-review.googlesource.com/2542
Reviewed-by: Rick Hudson <rlh@golang.org>

diff --git a/src/runtime/malloc.go b/src/runtime/malloc.go
index 772d3309d2ad4d14aed8f2717c5a5cb022260696..5cf45828229df3be64ba80b3577dd2cdf1b7e28d 100644 (file)
--- a/src/runtime/malloc.go
+++ b/src/runtime/malloc.go
@@ -655,17 +655,24 @@ func calctimes() gctimes {
 // the information from the most recent Concurent GC cycle. Calls from the
 // application to runtime.GC() are ignored.
 func GCprinttimes() {
-       times := calctimes()
-       println("GC:", gctimer.count, "maxpause=", gctimer.maxpause, "Go routines=", allglen)
-       println("          sweep termination: max=", gctimer.max.sweepterm, "total=", gctimer.total.sweepterm, "cycle=", times.sweepterm, "absolute time=", gctimer.cycle.sweepterm)
-       println("          scan:              max=", gctimer.max.scan, "total=", gctimer.total.scan, "cycle=", times.scan, "absolute time=", gctimer.cycle.scan)
-       println("          installmarkwb:     max=", gctimer.max.installmarkwb, "total=", gctimer.total.installmarkwb, "cycle=", times.installmarkwb, "absolute time=", gctimer.cycle.installmarkwb)
-       println("          mark:              max=", gctimer.max.mark, "total=", gctimer.total.mark, "cycle=", times.mark, "absolute time=", gctimer.cycle.mark)
-       println("          markterm:          max=", gctimer.max.markterm, "total=", gctimer.total.markterm, "cycle=", times.markterm, "absolute time=", gctimer.cycle.markterm)
+       // Explicitly put times on the heap so printPhase can use it.
+       times := new(gctimes)
+       *times = calctimes()
        cycletime := gctimer.cycle.sweep - gctimer.cycle.sweepterm
-       println("          Total cycle time =", cycletime)
-       totalstw := times.sweepterm + times.installmarkwb + times.markterm
-       println("          Cycle STW time     =", totalstw)
+       pause := times.sweepterm + times.installmarkwb + times.markterm
+       gomaxprocs := GOMAXPROCS(-1)
+
+       printlock()
+       print("GC: #", gctimer.count, " ", cycletime, "ns @", gctimer.cycle.sweepterm, " pause=", pause, " maxpause=", gctimer.maxpause, " goroutines=", allglen, " gomaxprocs=", gomaxprocs, "\n")
+       printPhase := func(label string, get func(*gctimes) int64, procs int) {
+               print("GC:     ", label, " ", get(times), "ns\tmax=", get(&gctimer.max), "\ttotal=", get(&gctimer.total), "\tprocs=", procs, "\n")
+       }
+       printPhase("sweep term:", func(t *gctimes) int64 { return t.sweepterm }, gomaxprocs)
+       printPhase("scan:      ", func(t *gctimes) int64 { return t.scan }, 1)
+       printPhase("install wb:", func(t *gctimes) int64 { return t.installmarkwb }, gomaxprocs)
+       printPhase("mark:      ", func(t *gctimes) int64 { return t.mark }, 1)
+       printPhase("mark term: ", func(t *gctimes) int64 { return t.markterm }, gomaxprocs)
+       printunlock()
 }
 
 // GC runs a garbage collection.