From: Austin Clements Date: Thu, 26 Mar 2015 22:48:42 +0000 (-0400) Subject: runtime: update gctrace line for new garbage collector X-Git-Tag: go1.5beta1~1331 X-Git-Url: http://www.git.cypherpunks.su/?a=commitdiff_plain;h=24ee948269580391dda0e3ec50136d25a5778280;p=gostls13.git runtime: update gctrace line for new garbage collector 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 --- diff --git a/src/runtime/mgc.go b/src/runtime/mgc.go index 89f3fb5340..057f897415 100644 --- a/src/runtime/mgc.go +++ b/src/runtime/mgc.go @@ -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:] +} diff --git a/src/runtime/proc.go b/src/runtime/proc.go index edab9bfdd6..968d5e925b 100644 --- a/src/runtime/proc.go +++ b/src/runtime/proc.go @@ -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) })