英文:
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, #->#-># 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 <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("/")
} 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.
通过集体智慧和协作来改善编程学习和解决问题的方式。致力于成为全球开发者共同参与的知识库,让每个人都能够通过互相帮助和分享经验来进步。
评论