runtime: shrinkstack during mark termination significantly increases GC STW time

[rhysh]

I have a process that experiences significant STW times during the mark termination phase of garbage collection. When it has around 100,000 goroutines and a live heap of around 500MB, its STW pauses take tens of milliseconds. The process runs on linux/amd64 with GOMAXPROCS=18, with a recent version of Go tip (30b9663).

I profiled its CPU usage with perf_events, looking specifically at samples with runtime.gcMark on the stack. 7.5% of samples include runtime.gcMark -> runtime.freeStackSpans (non-parallelized work, discussed in #11465). 90% of samples include runtime.gcMark -> runtime.parfordo -> runtime.markroot, and 75% of samples include runtime.gcMark -> runtime.parfordo -> runtime.markroot -> runtime.shrinkstack.

The work for stack shrinking is split 18 ways in my case, but at 75% of CPU cycles it's still a huge contributor to mark termination pauses, and the pauses my program sees are well beyond the 10ms goal with only a modest heap size.

Does stack shrinking need to take place while the world is stopped?

$ go version
go version devel +30b9663 Tue Oct 13 21:06:58 2015 +0000 linux/amd64

@aclements

[ianlancetaylor]

CC @RLH @aclements

[randall77]

We could move stack shrinking to the phase where we stop one goroutine at a time.

[aclements]

I agree. I don't think there would be any problem with shrinking each stack right before we do the concurrent scan of that stack. We have to be careful not to use any cross-stack pointers between when we shrink our own stack and when we return from the system stack, but that may actually be easier to ensure if we do the shrink as part of stack scanning.

[rhysh]

I've written a reproducer, included below. Its perf_events profile, collected on linux/amd64, looks very similar to what I see for my production program in terms of CPU time spent in runtime.freeStackSpans (10%), in runtime.shrinkstack (83%), in runtime.stackalloc (37%), and in runtime.stackfree (37%).

The reproducer starts 10,000 goroutines which each repeatedly grow and shrink their stack by 10kB. The production program has around 200,000 goroutines and has a garbage collection every 60-120 seconds, so any goroutines that grow and shrink their stacks during that time will contribute to the mark termination pause. (Ironic that generating more garbage, which would lead to more frequent collections, could reduce the duration of each pause.)

Here's output from some runs of the program on darwin/amd64.

$ go version
go version devel +3bc0601 Tue Oct 20 03:16:09 2015 +0000 darwin/amd64

$ GODEBUG=gctrace=1 ./12967 
gc 1 @0.002s 20%: 22+9.1+0.15+2.4+0.72 ms clock, 45+9.1+0+0/4.5/0+1.4 ms cpu, 10->14->13 MB, 15 MB goal, 8 P
gc 2 @0.126s 7%: 0.24+24+0.001+0.065+0.50 ms clock, 0.48+24+0+1.0/0/6.2+1.0 ms cpu, 15->15->15 MB, 27 MB goal, 8 P
gc 3 @0.856s 1%: 0.31+24+0.001+0.067+0.54 ms clock, 2.4+24+0+1.4/0.001/10+4.3 ms cpu, 22->22->16 MB, 30 MB goal, 8 P
gc 4 @2.118s 0%: 0.25+24+0.001+0.066+0.51 ms clock, 2.0+24+0+0.029/0/13+4.1 ms cpu, 28->28->16 MB, 32 MB goal, 8 P
gc 5 @3.684s 2%: 0.19+20+0.002+0.068+79 ms clock, 1.5+20+0+0.95/0.003/6.7+638 ms cpu, 31->31->16 MB, 32 MB goal, 8 P
gc 6 @5.239s 2%: 0.36+24+0.001+0.10+0.53 ms clock, 2.9+24+0+0.031/0.021/13+4.2 ms cpu, 31->31->16 MB, 32 MB goal, 8 P
gc 7 @6.904s 1%: 0.25+29+0.002+0.069+0.59 ms clock, 2.0+29+0+7.2/0.002/0.039+4.7 ms cpu, 32->32->16 MB, 33 MB goal, 8 P
gc 8 @8.551s 1%: 0.22+20+0.002+0.065+23 ms clock, 1.8+20+0+1.7/0/7.1+185 ms cpu, 32->32->16 MB, 33 MB goal, 8 P
gc 9 @10.175s 1%: 0.24+25+0.001+0.071+0.57 ms clock, 1.9+25+0+0/0.014/10+4.5 ms cpu, 32->32->15 MB, 33 MB goal, 8 P
gc 10 @11.690s 1%: 0.21+26+0.002+0.072+0.60 ms clock, 1.6+26+0+5.6/0.002/0.016+4.8 ms cpu, 30->30->16 MB, 31 MB goal, 8 P
gc 11 @13.316s 1%: 0.25+23+0.001+0.054+13 ms clock, 2.0+23+0+1.8/0.006/12+105 ms cpu, 32->32->16 MB, 33 MB goal, 8 P
gc 12 @14.942s 1%: 0.24+19+0.001+0.059+8.8 ms clock, 1.9+19+0+0.80/0.001/7.1+70 ms cpu, 32->32->16 MB, 33 MB goal, 8 P
gc 13 @16.603s 1%: 0.22+25+0.001+0.085+0.61 ms clock, 1.7+25+0+3.8/0.020/7.4+4.9 ms cpu, 32->32->16 MB, 33 MB goal, 8 P
gc 14 @18.239s 1%: 0.22+20+0.001+0.15+14 ms clock, 1.7+20+0+0.034/0.010/10+112 ms cpu, 32->32->16 MB, 33 MB goal, 8 P
gc 15 @19.875s 1%: 0.23+21+0.001+0.069+9.7 ms clock, 1.8+21+0+0/0.002/8.1+78 ms cpu, 32->32->15 MB, 33 MB goal, 8 P
gc 16 @21.392s 0%: 0.21+23+0.001+0.067+0.59 ms clock, 1.6+23+0+0.26/0.002/10+4.7 ms cpu, 30->30->16 MB, 31 MB goal, 8 P
gc 17 @23.014s 0%: 0.20+21+0.001+0.067+13 ms clock, 1.6+21+0+1.7/0.015/9.0+105 ms cpu, 32->32->16 MB, 33 MB goal, 8 P

Disabling stack shrinking makes the mark termination STW pauses significantly shorter.

$ GODEBUG=gctrace=1,gcshrinkstackoff=1 ./12967 
gc 1 @0.002s 20%: 22+6.9+0.21+2.2+0.64 ms clock, 45+6.9+0+0/4.2/0+1.2 ms cpu, 10->14->13 MB, 15 MB goal, 8 P
gc 2 @0.128s 6%: 0.30+23+0.001+0.069+0.56 ms clock, 0.60+23+0+0.82/0.002/8.5+1.1 ms cpu, 15->15->15 MB, 27 MB goal, 8 P
gc 3 @0.841s 1%: 0.21+24+0.001+0.053+0.47 ms clock, 1.7+24+0+1.1/0.004/7.2+3.7 ms cpu, 22->22->16 MB, 30 MB goal, 8 P
gc 4 @2.059s 0%: 0.29+24+0.001+0.058+0.43 ms clock, 2.0+24+0+0/0.010/8.1+3.0 ms cpu, 28->28->15 MB, 32 MB goal, 8 P
gc 5 @3.475s 0%: 0.28+21+0.002+0.077+0.28 ms clock, 2.2+21+0+0.049/0.001/11+2.3 ms cpu, 29->29->16 MB, 30 MB goal, 8 P
gc 6 @4.995s 0%: 0.20+19+0.002+0.077+0.28 ms clock, 1.6+19+0+0/0.027/9.5+2.3 ms cpu, 31->31->15 MB, 32 MB goal, 8 P
gc 7 @6.509s 0%: 0.20+28+0.001+0.068+0.56 ms clock, 1.6+28+0+6.0/0.001/0.032+4.5 ms cpu, 30->30->16 MB, 31 MB goal, 8 P
gc 8 @8.138s 0%: 0.21+20+0.001+0.077+0.27 ms clock, 1.6+20+0+0/0.018/7.0+2.1 ms cpu, 32->32->15 MB, 33 MB goal, 8 P
gc 9 @9.652s 0%: 0.25+21+0.001+0.070+0.26 ms clock, 2.0+21+0+0.28/0.015/10+2.1 ms cpu, 30->30->16 MB, 31 MB goal, 8 P
gc 10 @11.275s 0%: 0.23+22+0.002+0.078+0.64 ms clock, 1.8+22+0+0/0.018/7.6+5.1 ms cpu, 32->32->15 MB, 33 MB goal, 8 P
gc 11 @12.791s 0%: 0.26+21+0.001+0.070+0.23 ms clock, 1.8+21+0+0/0.014/10+1.6 ms cpu, 30->30->15 MB, 31 MB goal, 8 P
gc 12 @14.302s 0%: 0.20+19+0.002+0.073+0.28 ms clock, 1.6+19+0+0/0.002/7.2+2.2 ms cpu, 30->30->15 MB, 31 MB goal, 8 P
gc 13 @15.815s 0%: 0.26+28+0.001+0.066+0.47 ms clock, 2.1+28+0+6.6/0/0.020+3.7 ms cpu, 30->30->16 MB, 31 MB goal, 8 P
gc 14 @17.441s 0%: 0.26+24+0.001+0.067+0.56 ms clock, 2.0+24+0+1.2/0.001/8.5+4.5 ms cpu, 32->32->16 MB, 33 MB goal, 8 P
gc 15 @19.064s 0%: 0.21+20+0.001+0.077+0.24 ms clock, 1.7+20+0+0/0.017/9.6+1.9 ms cpu, 32->32->15 MB, 33 MB goal, 8 P
gc 16 @20.577s 0%: 0.22+22+0.001+0.079+0.54 ms clock, 1.8+22+0+0/0.002/9.5+4.3 ms cpu, 30->30->15 MB, 31 MB goal, 8 P
gc 17 @22.091s 0%: 0.21+26+0.001+0.070+0.55 ms clock, 1.6+26+0+4.8/0.001/0.014+4.4 ms cpu, 30->30->16 MB, 31 MB goal, 8 P

package main

import (
    "sync"
    "time"
)

const (
    ballastSize   = 10 << 20
    garbageSize   = 1 << 20
    garbagePeriod = 100 * time.Millisecond

    stackCount  = 10000
    stackSize   = 10 << 10
    stackPeriod = 5 * time.Second
)

var (
    ballast []byte
    garbage []byte
)

func churn() {
    ballast = make([]byte, ballastSize)

    for {
        time.Sleep(garbagePeriod)
        garbage = make([]byte, garbageSize)
    }
}

func stack(a, b *sync.WaitGroup) {
    for {
        grow(a)
        b.Wait()
    }
}

func grow(a *sync.WaitGroup) byte {
    var s [stackSize]byte
    a.Wait()
    return s[0]
}

func main() {
    go churn()

    var a, b sync.WaitGroup
    a.Add(1)
    for i := 0; i < stackCount; i++ {
        go stack(&a, &b)
    }

    for {
        time.Sleep(stackPeriod / 2)
        b.Add(1)
        a.Add(-1)

        time.Sleep(stackPeriod / 2)
        a.Add(1)
        b.Add(-1)
    }
}

[aclements]

I thought of one problem with shrinking stacks during concurrent stack scan. If the goroutine is blocked in a channel operation or select, there are pointers in to that G's stack from runtime structures and updating these pointers during shrinking could race with another G completing that channel operation or select. This isn't an issue for stack growing because that's always done synchronously.

I can think of a few solutions:

1. We could not shrink the stack concurrently. This would be unfortunate, since goroutines are often blocked on channels for a long time.

2. The stack shrinking code could detect this condition and lock the appropriate channels while shrinking to prevent a channel operation from completing during the shrink. This might not be so hard: we could add the *hchan to the sudog and then walk the g.waiting list in shrinkstack. We'd probably want to rearrange copystack a bit so we didn't have to keep these channels locked for the whole copystack. This has the downside of blocking all other operations on these channels even if the G being shrunk is way back in the channel's queue.

3. Channel operations could detect this condition and wait for the stack shrink to finish or just requeue the waiting G (which doesn't help if this is the only G waiting on the channel). Channel operations would also have to block a stack shrink from starting during the operation. This has the advantage of only blocking operations that actually deal with the G being shrunk. We could probably do this by synchronizing on the G's status. Introduce a new status for "in a channel op" and make the channel completion put the G in to this status. If the G is in _Gcopystack, that will spin until the copy stack is done. If it's not in _Gcopystack, that will cause a copystack to spin during the channel op completion until it can put it in to _Gcopystack.

[rhysh]

Does your first solution mean that the stacks would be shrunk during a STW phase, or that they would not be shrunk at all?

Most of the goroutines in the application I described are blocked on channel operations nearly all the time. The goroutines occasionally get a message on their channel that makes them call a function with a large stack requirement (and which returns quickly).

Locking all goroutines that are attempting to communicate on a channel, as described in the second solution, would make "quit" channels more expensive if shared across many goroutines. Stack shrinking on any one of the participating goroutines would delay all of the others.

The third solution seems easy to reason about, and sounds like it will have predictable performance.

[rsc]

Per Austin, this is too invasive for Go 1.6. He may look into having it ready for the start of the 1.7 cycle.

[randall77]

So as I see it there are a couple of options to enable shrinking outside a STW phase.

1. Have receivers allocate space for the received data on the heap.
2. Have unbuffered channels allocate one slot which is used to pass the sent value.
3. Shrinker must grab the channel lock.
4. Sender & shrinker must grab a lock on the stack (or G, as Austin proposes)
5. Shrink stacks in place.

1 means allocation per channel receive.
2 means some extra memory + some extra synchronization.
3 might be difficult for select statements, we'd need to grab all the chan locks.
4 means a second lock per send.
5 means possibly greater fragmentation.

As others have also pointed out, I don't think preventing shrinking while in receive is a viable option.
Any others?

[ianlancetaylor]

You probably considered this, but everything flows through the sudog, so we could add a lock there. Once the sudog is selected for a channel op, we can lock it. Stack shrinking already knows about the sudogs associated with the channel, it could lock all of them first. If stack shrinking sees that a sudog is already locked, it can punt and wait until next time. If the channel op sees that the sudog is locked, we know there can be at must one channel op pending for a goroutine, so the channel op can sleep on a note until the stack shrinking is complete. So I think the sudog lock can be a single atomic integer managed through cas, plus a note. I think the overhead in the normal case is one additional atomic cas and one atomic store per channel send.

[aclements]

@RLH and I were talking about another solution that sort of combines @randall77's first suggestion and @ianlancetaylor's suggestion: reserve a few words in the sudog for receiving small values (which are presumably the majority of channel ops) and otherwise allocate space on the heap for a slot. The receiver would then copy the value in to its own stack when it wakes up. This would eliminate cross-stack writes, at the cost of slightly larger sudogs and a heap allocation for passing large values.