gctrace中与时间相关的字段

huangapple go评论133阅读模式
英文:

Timing-related fields in gctrace

问题

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

我用以下命令获取统计信息:

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

现在,文档中说:

gctrace: 设置gctrace=1会导致垃圾收集器在每次收集时向标准错误输出一行摘要,摘要包括收集的内存量和暂停的长度。设置gctrace=2会输出相同的摘要,但会重复每次收集。此行的格式可能会更改。目前的格式是:
    gc # @#s #%: #+#+# ms clock, #+#/#/#+# ms cpu, #->#-># MB, # MB goal, # P
其中字段的含义如下:
    gc #        GC编号,每次GC时递增
    @#s         程序启动后的秒数
    #%          自程序启动以来在GC上花费的时间的百分比
    #+...+#     GC各阶段的墙钟/CPU时间
    #->#-># MB  GC开始时的堆大小、GC结束时的堆大小和活动堆大小
    # MB goal   目标堆大小
    # P         使用的处理器数量
各阶段包括停止世界(STW)扫描终止、并发标记和扫描以及STW标记终止。标记/扫描的CPU时间分为辅助时间(与分配同时进行的GC)、后台GC时间和空闲GC时间。
如果行以“(forced)”结尾,则此GC是由runtime.GC()调用强制执行的,所有阶段都是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 <br/>
> 1.9+0/1412/3894+38 ms cpu

根据文档:

STW扫描终止:0.061毫秒
并发标记和扫描:86毫秒
STW标记终止:1.2毫秒

现在第二组时间应该是先前标记/扫描时间的详细说明。但它们似乎相当大(3894毫秒?),我不理解其中的+符号。它们表示什么,为什么详细说明比值要大?

英文:

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, #-&gt;#-&gt;# 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
    #-&gt;#-&gt;# 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 &quot;(forced)&quot;, 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-&gt;1095-&gt;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 <br/>
> 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?

答案1

得分: 1

源代码位于runtime/mgc.go文件中:

for i, ns := range []int64{
    sweepTermCpu, 
    gcController.assistTime, 
    gcController.dedicatedMarkTime + gcController.fractionalMarkTime,
    gcController.idleMarkTime, 
    markTermCpu} {
    if i == 2 || i == 3 {
        // 使用/分隔标记时间组件。
        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表示在此周期内在空闲标记中花费的纳秒数。不足为奇的是,GC利用空闲处理器进行一些标记操作。

// gcMarkWorkerIdleMode表示P正在运行标记工作器,因为它没有其他任务可执行。
// 空闲工作器应该一直运行,直到被抢占,并将其时间计入gcController.idleMarkTime。
gcMarkWorkerIdleMode

实际上,有一个待处理的问题14179指出GC的工作量不够(!),应该唤醒空闲的处理器。

英文:

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(&quot;/&quot;)
	} else if i != 0 {
		print(&quot;+&quot;)
	}
	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.

huangapple
  • 本文由 发表于 2016年12月30日 12:07:01
  • 转载请务必保留本文链接:https://go.coder-hub.com/41390479.html
匿名

发表评论

匿名网友

:?: :razz: :sad: :evil: :!: :smile: :oops: :grin: :eek: :shock: :???: :cool: :lol: :mad: :twisted: :roll: :wink: :idea: :arrow: :neutral: :cry: :mrgreen:

确定