go - gctrace中与时间相关的字段

Question

我试图了解在运行一组从 Go (v1.7) 程序编译的可执行文件的系统上启用 GODEBUG=gctrace=1 时提到的确切时间字段。

我用来获取统计信息的命令是:

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

现在，文档说:

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.

输出的示例行是:

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

我想了解的是与时间相关的一对字段:

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

所以根据文档:

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

现在第二组时间应该是之前标记/扫描时间的分割。但它们似乎相当大(3894 ms ？)，而且我不理解其中的 +。它们表示什么以及分割如何显示大于值？

Answer 1

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))))
}

所以 1.9+0/1412/3894+38 ms cpu 意味着:

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

与 gcController.idleMarkTime是在 idle marking 中花费的纳秒在这个周期内。
GC 利用空闲处理器做一些标记并不奇怪。

// 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

实际上有一个pending issue 14179说明 GC 做得不够(!)，应该唤醒空闲处理器。