Decipher garbage collection output

Question

I was running a sample program program using

rahul@g3ck0:~/programs/Remodel$ GOGCTRACE=1 go run main.go 
gc1(1): 0+0+0 ms 0 -> 0 MB 422 -> 346 (422-76) objects 0 handoff
gc2(1): 0+0+0 ms 0 -> 0 MB 2791 -> 1664 (2867-1203) objects 0 handoff
gc3(1): 0+0+0 ms 1 -> 0 MB 4576 -> 2632 (5779-3147) objects 0 handoff
gc4(1): 0+0+0 ms 1 -> 0 MB 3380 -> 2771 (6527-3756) objects 0 handoff
gc5(1): 0+0+0 ms 1 -> 0 MB 3511 -> 2915 (7267-4352) objects 0 handoff
gc6(1): 0+0+0 ms 1 -> 0 MB 6573 -> 2792 (10925-8133) objects 0 handoff
gc7(1): 0+0+0 ms 1 -> 0 MB 4859 -> 3059 (12992-9933) objects 0 handoff
gc8(1): 0+0+0 ms 1 -> 0 MB 4554 -> 3358 (14487-11129) objects 0 handoff
gc9(1): 0+0+0 ms 1 -> 0 MB 8633 -> 4116 (19762-15646) objects 0 handoff
gc10(1): 0+0+0 ms 1 -> 0 MB 9415 -> 4769 (25061-20292) objects 0 handoff
gc11(1): 0+0+0 ms 1 -> 0 MB 6636 -> 4685 (26928-22243) objects 0 handoff
gc12(1): 0+0+0 ms 1 -> 0 MB 6741 -> 4802 (28984-24182) objects 0 handoff
gc13(1): 0+0+0 ms 1 -> 0 MB 9654 -> 5097 (33836-28739) objects 0 handoff
gc1(1): 0+0+0 ms 0 -> 0 MB 209 -> 171 (209-38) objects 0 handoff

Help me understand the first part i.e.

0 + 0 + 0 => Mark + Sweep + Clean times

Does 422 -> 346 means that there has been memory cleanup from 422MB to 346 MB? If yes, then how come the memory is been reduced when there was nothing to be cleaned up?

Answer 1

In Go 1.5, the format of this output has changed considerably. For the full documentation, head over to http://godoc.org/runtime and search for "gctrace:"

gctrace: setting gctrace=1 causes the garbage collector to emit a single line to standard
error at each collection, summarizing the amount of memory collected and the
length of the pause. Setting gctrace=2 emits the same summary but also
repeats each collection. The format of this line is subject to change.
Currently, it is:
    gc # @#s #%: #+...+# ms clock, #+...+# ms cpu, #->#-># MB, # MB goal, # P
where the fields are as follows:
    gc #        the GC number, incremented at each GC
    @#s         time in seconds since program start
    #%          percentage of time spent in GC since program start
    #+...+#     wall-clock/CPU times for the phases of the GC
    #->#-># MB  heap size at GC start, at GC end, and live heap
    # MB goal   goal heap size
    # P         number of processors used
The phases are stop-the-world (STW) sweep termination, scan,
synchronize Ps, mark, and STW mark termination. The CPU times
for mark are broken down in to assist time (GC performed in
line with allocation), background GC time, and idle GC time.
If the line ends with "(forced)", this GC was forced by a
runtime.GC() call and all phases are STW.

Answer 2

The output is generated from this line: http://golang.org/src/pkg/runtime/mgc0.c?#L2147

So the different parts are:

• 0+0+0 ms : mark, sweep and clean duration in ms
• 1 -> 0 MB : heap before and after in MB
• 209 - 171 : objects before and after
• (209-38) objects : number of allocs and frees

handoff (and in Go 1.2 steal and yields) are internals of the algorithm.