gctrace中与计时相关的字段

Question

I am trying to understand the exact timing fields that are mentioned when GODEBUG=gctrace=1 is enabled on a system running a set of executables compiled from a Go (v1.7) program.

The command I use to get the stats is:

GODEBUG=gctrace=1 ~/golang/go/bin/godoc -http=:5555 -index

Now, the documentation says:

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, concurrent
mark and scan, and STW mark termination. The CPU times
for mark/scan 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.

A sample line of the output is:

gc 408 @4005.361s 0%: 0.061+86+1.2 ms clock, 1.9+0/1412/3894+38 ms cpu, 1080->1095->556 MB, 1108 MB goal, 72 P

What I a trying to understand are the pair of fields related to time:

0.061+86+1.2 ms clock
1.9+0/1412/3894+38 ms cpu

So as per the documentation:

STW sweep termination: 0.061 ms
Concurrent mark and scan: 86 ms
STW mark termination: 1.2 ms

Now the second set of times are supposed to be a breakdown of the mark/scan times earlier. But they seem to be quite large (3894 ms ?), and I don't understand the + in the mix. What do they indicate and how does the breakdown appear larger than the values?

Answer 1

The source code is in runtime/mgc.go:

for i, ns := range []int64{
    sweepTermCpu, 
    gcController.assistTime, 
    gcController.dedicatedMarkTime + gcController.fractionalMarkTime,
    gcController.idleMarkTime, 
    markTermCpu} {
    if i == 2 || i == 3 {
        // Separate mark time components with /.
        print("/")
    } else if i != 0 {
        print("+")
    }
    print(string(fmtNSAsMS(sbuf[:], uint64(ns))))
}

So 1.9+0/1412/3894+38 ms cpu means:

   1.9 sweepTermCpu, 
   0   gcController.assistTime, 
1412   gcController.dedicatedMarkTime + gcController.fractionalMarkTime,
3894   gcController.idleMarkTime, 
  38   markTermCpu

With gcController.idleMarkTime being the nanoseconds spent in idle marking during this cycle.
It is not surprising the the GC takes advantage of an idle processor to do some marking.

// gcMarkWorkerIdleMode indicates that a P is running the mark
// worker because it has nothing else to do. The idle worker
// should run until it is preempted and account its time
// against gcController.idleMarkTime.
gcMarkWorkerIdleMode

There is actually a pending issue 14179 stating that the GC does not do enough(!) and should wake up idle Processor.