解读垃圾回收输出

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

Decipher garbage collection output

问题

我正在运行一个使用以下命令的示例程序:

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

帮助我理解第一部分,即

> 0 + 0 + 0 => 标记 + 清除 + 清理时间

422 -> 346 是否意味着从 422MB 清理到 346 MB?如果是的话,那么当没有要清理的内容时,内存是如何减少的?

英文:

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?

答案1

得分: 7

在Go 1.5中,此输出的格式发生了很大的变化。有关完整的文档,请访问http://godoc.org/runtime并搜索"gctrace:"。

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)扫描终止、扫描、同步Ps、标记和STW标记终止。标记的CPU时间分为辅助时间(与分配同时进行的GC)、后台GC时间和空闲GC时间。如果行以"(forced)"结尾,则此GC是由runtime.GC()调用强制执行的,所有阶段都是STW。

英文:

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.

答案2

得分: 4

输出是从这一行生成的:http://golang.org/src/pkg/runtime/mgc0.c?#L2147

所以不同的部分是:

  • 0+0+0 ms:标记、清扫和清理的持续时间(以毫秒为单位)
  • 1 -> 0 MB:堆在之前和之后的大小(以MB为单位)
  • 209 - 171:之前和之后的对象数量
  • (209-38)个对象:分配和释放的数量

handoff(以及在Go 1.2中的steal和yield)是算法的内部部分。

英文:

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.

huangapple
  • 本文由 发表于 2013年12月13日 02:48:44
  • 转载请务必保留本文链接:https://go.coder-hub.com/20551748.html
匿名

发表评论

匿名网友

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

确定