阅读Go的gctrace输出。

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

Reading Go gctrace output

问题

我有一个类似这样的gctrace输出:

gc 6 @48.155s 15%: 0.093+12360+0.32 ms clock, 0.18+7720/21356/3615+0.65 ms cpu, 11039->13278->6876 MB, 14183 MB goal, 8 P

我不确定如何解读CPU时间,特别是其中的部分。我知道它被分为三个阶段(STW sweep termination,concurrent mark/scan和STW mark termination),但我不确定+符号的含义(例如0.18+77203615+0.65)。这些+符号表示什么?

英文:

I have gctrace output that looks like this:

gc 6 @48.155s 15%: 0.093+12360+0.32 ms clock, 0.18+7720/21356/3615+0.65 ms cpu, 11039->13278->6876 MB, 14183 MB goal, 8 P

I am not sure how to read the CPU times in particular. I understand that it is broken down into three phases (STW sweep termination, concurrent mark/scan, and STW mark termination), but I'm not sure what the + signs mean (i.e. 0.18+7720 and 3615+0.65). What do these + signs signify?

答案1

得分: 2

在你的情况下,它们看起来像是辅助时间和终止时间;

// CPU时间
0.18    : **STW** 停止-扫描终止。
7720毫秒  : 标记/扫描 - 辅助时间(与分配一致的垃圾回收)。
21356毫秒 : 标记/扫描 - 后台垃圾回收时间。
3615毫秒  : 标记/扫描 - 空闲垃圾回收时间。
0.65毫秒  : **STW** 标记终止。

我认为它会随着不同的Go版本而改变(或可能改变),你可以在runtime包文档中找到更详细的信息。

目前,它是这样的:
gc # @#s #%: #+#+# ms clock, #+#/#/#+# ms cpu, #->#-># MB, # MB goal, # P
其中字段的含义如下:
gc # 垃圾回收的次数,每次垃圾回收时递增
@#s 程序启动后经过的秒数
#% 自程序启动以来在垃圾回收中花费的时间百分比
#+...+# 垃圾回收各阶段的墙钟时间/ CPU时间
#->#-># MB 垃圾回收开始时、结束时和活跃堆的堆大小
# MB goal 目标堆大小
# P 使用的处理器数量

示例在这里

另请参阅解释GC跟踪输出

gc 6 @48.155s 15%: 0.093+12360+0.32 ms clock,
0.18+7720/21356/3615+0.65 ms cpu, 11039->13278->6876 MB, 14183 MB goal, 8 P
  • gc 6
  • @48.155s 程序启动后经过的时间
  • 15%: 自程序启动以来在垃圾回收中花费的时间百分比
  • 0.093+12360+0.32 ms clock 停止-扫描终止 + 并发标记和扫描 + 停止-扫描终止
  • 0.18+7720/21356/3615+0.65 ms cpu (与分配一致的垃圾回收),后台垃圾回收时间和空闲垃圾回收时间
  • 11039->13278->6876 MB 垃圾回收开始时、结束时和活跃堆的堆大小
  • 8 P 使用的处理器数量
英文:

In your case, they look like assist and termination times;

// CPU time
0.18    : **STW** Sweep termination.
7720ms  : Mark/Scan - Assist Time (GC performed in line with allocation).
21356ms : Mark/Scan - Background GC time.
3615ms  : Mark/Scan - Idle GC time.
0.65ms  : **STW** Mark termination.

I think it changes (or it may) over various Go versions and you can find more detailed info at runtime package docs.

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

Example here

See also Interpreting GC trace output

gc 6 @48.155s 15%: 0.093+12360+0.32 ms clock,
0.18+7720/21356/3615+0.65 ms cpu, 11039->13278->6876 MB, 14183 MB goal, 8 P
  • gc 6
  • @48.155s since program start
  • 15%: of time spent in GC since program start
  • 0.093+12360+0.32 ms clock stop-the-world (STW) sweep termination + concurrent
    mark and scan + and STW mark termination
  • 0.18+7720/21356/3615+0.65 ms cpu (GC performed in
    line with allocation), background GC time, and idle GC time
  • 11039->13278->6876 MB heap size at GC start, at GC end, and live heap
  • 8 P number of processors used

huangapple
  • 本文由 发表于 2017年2月22日 08:52:58
  • 转载请务必保留本文链接:https://go.coder-hub.com/42380784.html
匿名

发表评论

匿名网友

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

确定