Behavior of CPU/allocations for small, unsegmented heaps vs large, segmented heaps

[Travis Bischel]

I've attached a program that has a few options for testing different heap/cpu behavior. What I'm running into is that if a program transitions from a state of a large amount of in-use objects to a small amount of in-use objects, the CPU spikes, and I'm really curious as to why this happens.

By default, my attached program runs generating slices from 4KiB to 12KiB and immediately dropping them. On my laptop, this eats ~50-70%cpu. However, if the program is run with the option to create a large, fragmented heap (-start-bufs 3000000) and then transitions into a state of dropping everything it allocates, the CPU hovers at ~155-170%. I would expect the program to transition back to the ~50-70%cpu state. Additionally, while creating the fragmented memory, it hovers around ~70%cpu (this can be further tested with the -start-batches flag), meaning only after transitioning to a stable low memory in-use state does the cpu double.

From pprof, if the program starts without a fragmented heap, we see that most of the CPU is spent scheduling goroutines:

     1.56s 41.49% 41.49%      1.56s 41.49%  runtime.usleep

     0.44s 11.70% 53.19%      0.44s 11.70%  runtime.futex

     0.42s 11.17% 64.36%      0.62s 16.49%  runtime.scanobject

     0.10s  2.66% 67.02%      0.17s  4.52%  runtime.greyobject

     0.08s  2.13% 69.15%      1.56s 41.49%  runtime.findrunnable

If it starts with a fragmented heap (-start-bufs 3000000), we see that most of the CPU is spent doing memory management:

    13.96s 35.64% 35.64%     26.11s 66.66%  runtime.sweepone

    12.13s 30.97% 66.61%     12.13s 30.97%  runtime/internal/atomic.Xadd

    11.93s 30.46% 97.06%     11.93s 30.46%  runtime.markrootSpans

     0.49s  1.25% 98.32%      0.49s  1.25%  runtime.updatememstats

     0.02s 0.051% 98.37%     11.99s 30.61%  runtime.markroot

I've captured trace profiles as well. The good.png shows that, when started without a fragmented heap, the creator goroutine runs in bursts of ~2microseconds. bad.png shows that, when started with a fragmented heap, the creator goroutine takes ~45ms to run.

Without a fragmented heap, the program generates nearly the 10,000 bufs per second configured by default, whereas with a fragmented heap, it hovers at less than half (3,500-4,000):

Unfragmented:

===

total created: 3073959

since last: 9676

mem alloc: 3219312

mem sys: 9509112

last gc pause: 0.137094ms

since last gc: 32.908752ms

cpu pct: 75.6036%

Fragmented:

===

total created: 3072621

since last: 3660

mem alloc: 3416744

mem sys: 28169871664

last gc pause: 0.288073ms

since last gc: 51.318585ms

cpu pct: 141.3548%

Basically, all my investigation shows that something about the go runtime doesn't handle this specific allocation pattern all that well, and I'm wondering if that's by design, incidental, or accidental. Is this to be expected?

[Austin Clements]

Thanks for the detailed description. I suspect this is https://github.com/golang/go/issues/9265. Can you try the series that ends at https://go-review.googlesource.com/30537/?

--
You received this message because you are subscribed to the Google Groups "golang-dev" group.
To unsubscribe from this group and stop receiving emails from it, send an email to golang-dev+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[tra...@fastly.com]

Thanks Austin - I checked out that branch and confirmed that it eliminates the issue for this code and all other more complicated versions I had written. I remember seeing that issue a long time ago and wish I remembered it before digging in.

Cheers!

To unsubscribe from this group and stop receiving emails from it, send an email to golang-dev+...@googlegroups.com.