Yes, truncating the digits (instead of rounding) indeed explains it. Thanks Austin!
On Wed, Jun 22, 2016 at 5:30 PM, Austin Clements <aus...@google.com> wrote: > 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.
