From babeb4a963126e4c543ec717ef25ab1173833ae0 Mon Sep 17 00:00:00 2001 From: Austin Clements Date: Wed, 7 Jan 2015 15:34:02 -0500 Subject: [PATCH] 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 --- src/runtime/malloc.go | 27 +++++++++++++++++---------- 1 file changed, 17 insertions(+), 10 deletions(-) diff --git a/src/runtime/malloc.go b/src/runtime/malloc.go index 772d3309d2ad4..5cf45828229df 100644 --- 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.