qbit/go
1
0
Fork 0
mirror of https://github.com/golang/go synced 2024-11-19 02:04:42 -07:00
Code Releases Activity

runtime: improve GC times printing

Browse Source 
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>
This commit is contained in:
Austin Clements 2015-01-07 15:34:02 -05:00
parent 067acd51b0
commit babeb4a963
1 changed files with 17 additions and 10 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

27
src/runtime/malloc.go
View File

@ -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.