runtime: GC pause time 20% increase in 1.8beta1 compared to 1.7.3

[frje]

On my 64bits Windows 10 machine, the following benchmark https://gitlab.com/gasche/gc-latency-experiment/blob/master/main.go (with msgCount increased to 100M) display a worst time of 15.50ms in 1.8beta1 and 13.00ms in 1.7.3.

[bradfitz]

/cc @aclements @RLH

[bradfitz]

I suspect time.Now() isn't a great way to measure, especially on Windows.

What is the output with GODEBUG=gctrace=1 set in the environment and then running your program under both Go 1.7 and Go 1.8beta1?

[aclements]

There might be a performance regression here, but nothing in this benchmark indicates that it's specifically a GC pause time regression (in fact, it's highly unlikely that it is). In addition to Brad's suggestion, looking at the execution trace may be enlightening.

[rhysh]

@aclements I looked into this test program yesterday (from a blog post via golang-nuts), and it looks like there's GC involvement. After the GC completes, allocation needs to assist with sweep—and when the heap is growing in the first 1/5th of that program, sweep assists won't find any garbage. Single allocations are delayed until the entire heap is swept.

I didn't do any comparison with go1.7.3, so can't speak to a regression.

I filed #18155 with details on what I found.

[frje]

1.7.3:
log1.7.3.txt
...
gc 527 @57.745s 6%: 0+6.0+5.9 ms clock, 0+0/12/36+47 ms cpu, 381->381->195 MB, 391 MB goal, 8 P
gc 528 @57.854s 6%: 0+8.0+5.9 ms clock, 0+0/8.0/50+47 ms cpu, 381->381->195 MB, 391 MB goal, 8 P
gc 529 @57.966s 6%: 0+6.5+5.0 ms clock, 0+0/12/36+40 ms cpu, 381->381->195 MB, 391 MB goal, 8 P
gc 530 @58.074s 6%: 0+7.9+5.5 ms clock, 0+0/15/46+44 ms cpu, 381->381->195 MB, 391 MB goal, 8 P
gc 531 @58.187s 6%: 0+5.9+6.0 ms clock, 0+0/5.9/41+48 ms cpu, 381->381->195 MB, 391 MB goal, 8 P

1.8beta1
log1.8beta1.txt
...
gc 525 @56.566s 1%: 0+9.0+0 ms clock, 0+9.0/9.9/3.9+0 ms cpu, 385->385->195 MB, 395 MB goal, 8 P
gc 526 @56.674s 1%: 0+9.0+0 ms clock, 0+9.0/0/9.0+0 ms cpu, 381->381->195 MB, 390 MB goal, 8 P
gc 527 @56.780s 1%: 0+9.0+1.0 ms clock, 0+9.0/10/5.0+8.0 ms cpu, 381->382->196 MB, 390 MB goal, 8 P
gc 528 @56.887s 1%: 0+9.0+0 ms clock, 0+9.0/1.9/12+0 ms cpu, 383->383->195 MB, 393 MB goal, 8 P
gc 529 @56.993s 1%: 0+7.9+0 ms clock, 0+7.9/7.9/0+0 ms cpu, 381->381->195 MB, 390 MB goal, 8 P

[frje]

stop-the-world (STW) sweep termination concurrent mark seems to be taking more CPU time 0+9.0 compared to 0+0

[aclements]

Thanks for the gctrace. It's showing that your STW sweep termination and STW mark termination times in 1.8beta1 are less than a microsecond in both wall-clock and CPU time (except in gc 527). The "9.0" in "0+9.0" belongs to concurrent mark, not sweep term.

I think @rhysh is on to something, though. If you grab an execution trace with 1.8 and post it here, I can probably confirm his findings.

[frje]

I've updated the previous post with the full traces as attachments (both 1.7.3 and 1.8beta1). I’ve also looked at what the resolution might be for time.Now on Windows. It’s complicated but I’m reasonably confident it’s around 1 micro-second on my machine. So measurement differences of 2.5 milliseconds could not be rounding errors. (I assume ms stand for millisecond not micro).

[RLH]

After reading Rhys's post I was able to convince myself if half the spans contain no free objects then a single allocation may end up scanning half the heap's allocation bits. This is complicated by the fact that the allocation fast path has be optimized for exactly the opposite situation, where there are lots of free objects in each span. One possible way to resolve this is to scan the spans in a pseudo random order so that if half the object's are free finding a span with one should not take too many tries, Certainly not half the spans. Perhaps the random choice is only done by assists that are trying to allocate.

…

On Fri, Dec 2, 2016 at 12:26 PM, Austin Clements ***@***.***> wrote: Thanks for the gctrace. It's showing that your STW sweep termination and STW mark termination times in 1.8beta1 are less than a microsecond in both wall-clock and CPU time (except in gc 527). The "9.0" in "0+9.0" belongs to concurrent mark, not sweep term. I think @rhysh <https://github.com/rhysh> is on to something, though. If you grab an execution trace with 1.8 and post it here, I can probably confirm his findings. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#18161 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AA7Wn9MtzZbWYyVGKwBU6T38N0zICEpjks5rEFTIgaJpZM4LCmtu> .

[aclements]

@frje, can you try applying https://golang.org/cl/34291 and see if that helps?

[frje]

@aclements It looks like my original conclusion was probably wrong : 1.8beta1 does not get longer pauses than 1.7.3 it’s just that the benchmark is inherently imprecise and results are quite volatiles. I’ve now run the benchmark multiple times with billions of calls.
What I get is this:

1.7.3
16-22.5ms

1.8Beta1
15-16ms

34291
19-20ms

As far as I’m concerned, this issue should be closed.

[bradfitz]

Closing, thanks for the update.