I think what you're seeing is simply rounding in the values printed by the gctrace. You're correct that the two metrics are reporting the same thing. In fact, they come from the exact same time stamps internally. But formatting floating point numbers is hard. :) The gctrace printer simply truncates the printed value to a reasonable number of digits, so, for example, the 0.20ms in your second GC might actually be 0.207ms.
On Wed, Jun 22, 2016 at 5:55 PM, Caleb Spare <cesp...@gmail.com> wrote: > Hi, > > I'm looking at GC statistics using both GODEBUG=gctrace=1 and > debug.ReadGCStats. My question is: should the pause durations reported > in debug.GCStats match the sum of the two STW phases listed in the > gctrace? > > I ask because they are generally close but not the same. I have a > trivial program (https://play.golang.org/p/9NYDjBW6ei) that prints gc > stats; when I run it with GODEBUG=gctrace=1, I see output like this: > > LastGC: 1969-12-31T16:00:00-08:00 NumGC: 0 PauseTotal: 0 Pause: [] > LastGC: 1969-12-31T16:00:00-08:00 NumGC: 0 PauseTotal: 0 Pause: [] > LastGC: 1969-12-31T16:00:00-08:00 NumGC: 0 PauseTotal: 0 Pause: [] > gc 1 @3.427s 0%: 0.046+0.20+0.060 ms clock, 0.14+0.024/0.13/0.13+0.18 > ms cpu, 4->4->0 MB, 5 MB goal, 4 P > LastGC: 2016-06-22T16:46:13-07:00 NumGC: 1 PauseTotal: 106.965µs > Pause: [106.965µs] > LastGC: 2016-06-22T16:46:13-07:00 NumGC: 1 PauseTotal: 106.965µs > Pause: [106.965µs] > LastGC: 2016-06-22T16:46:13-07:00 NumGC: 1 PauseTotal: 106.965µs > Pause: [106.965µs] > LastGC: 2016-06-22T16:46:13-07:00 NumGC: 1 PauseTotal: 106.965µs > Pause: [106.965µs] > gc 2 @7.320s 0%: 0.008+0.14+0.20 ms clock, 0.033+0/0.098/0.13+0.82 ms > cpu, 4->4->0 MB, 5 MB goal, 4 P > LastGC: 2016-06-22T16:46:17-07:00 NumGC: 2 PauseTotal: 322.029µs > Pause: [215.064µs 106.965µs] > > For the first GC, gctrace shows 0.046ms + 0.060ms = 106µs vs 106.965µs > from ReadGCStats. > For the second GC, gctrace shows 0.008ms + 0.20ms = 208µs vs 215.064µs > from ReadGCStats. > > I'm trying to understand whether these two metrics are reporting > essentially the same thing (as is my understanding), or whether there > is some source of STW pause time ReadGCStats is showing me that isn't > exposed in the gctrace. > > (I see similar results on 1.6.2 and tip.) > > Thanks! > Caleb > -- You received this message because you are subscribed to the Google Groups "golang-nuts" group. To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscr...@googlegroups.com. For more options, visit https://groups.google.com/d/optout.
