Why does a "concurrent" Go GC phase appear to be stop-the-world?
<p>I am attempting to benchmark the maximum STW GC pause time for different numbers of heap objects. To do this I have written a simple benchmark that pushes and pops messages from a <code>map</code>:</p>

<pre><code>package main

type message []byte

type channel map[int]message

const (
    windowSize = 200000
    msgCount   = 1000000
)

func mkMessage(n int) message {
    m := make(message, 1024)
    for i := range m {
        m[i] = byte(n)
    }
    return m
}

func pushMsg(c *channel, highID int) {
    lowID := highID - windowSize
    m := mkMessage(highID)
    (*c)[highID] = m
    if lowID &gt;= 0 {
        delete(*c, lowID)
    }
}

func main() {
    c := make(channel)
    for i := 0; i &lt; msgCount; i++ {
        pushMsg(&amp;c, i)
    }
}
</code></pre>

<p>I ran this with <a href="https://golang.org/pkg/runtime/" rel="nofollow"><code>GODEBUG=gctrace=1</code></a>, and on my machine the output is:</p>

<pre><code>gc 1 @0.004s 2%: 0.007+0.44+0.032 ms clock, 0.029+0.22/0.20/0.28+0.12 ms cpu, 4-&gt;4-&gt;3 MB, 5 MB goal, 4 P
gc 2 @0.009s 3%: 0.007+0.64+0.042 ms clock, 0.030+0/0.53/0.18+0.17 ms cpu, 7-&gt;7-&gt;7 MB, 8 MB goal, 4 P
gc 3 @0.019s 1%: 0.007+0.99+0.037 ms clock, 0.031+0/0.13/1.0+0.14 ms cpu, 13-&gt;13-&gt;13 MB, 14 MB goal, 4 P
gc 4 @0.044s 2%: 0.009+2.3+0.032 ms clock, 0.039+0/2.3/0.30+0.13 ms cpu, 25-&gt;25-&gt;25 MB, 26 MB goal, 4 P
gc 5 @0.081s 1%: 0.009+9.2+0.082 ms clock, 0.039+0/0.32/9.7+0.32 ms cpu, 49-&gt;49-&gt;48 MB, 50 MB goal, 4 P
gc 6 @0.162s 0%: 0.020+10+0.078 ms clock, 0.082+0/0.28/11+0.31 ms cpu, 93-&gt;93-&gt;91 MB, 96 MB goal, 4 P
gc 7 @0.289s 0%: 0.020+27+0.092 ms clock, 0.080+0/0.95/28+0.37 ms cpu, 178-&gt;178-&gt;173 MB, 182 MB goal, 4 P
gc 8 @0.557s 1%: 0.023+38+0.086 ms clock, 0.092+0/38/10+0.34 ms cpu, 337-&gt;339-&gt;209 MB, 346 MB goal, 4 P
gc 9 @0.844s 1%: 0.008+40+0.077 ms clock, 0.032+0/5.6/46+0.30 ms cpu, 407-&gt;409-&gt;211 MB, 418 MB goal, 4 P
gc 10 @1.100s 1%: 0.009+43+0.047 ms clock, 0.036+0/6.6/50+0.19 ms cpu, 411-&gt;414-&gt;212 MB, 422 MB goal, 4 P
gc 11 @1.378s 1%: 0.008+45+0.093 ms clock, 0.033+0/6.5/52+0.37 ms cpu, 414-&gt;417-&gt;213 MB, 425 MB goal, 4 P
</code></pre>

<p>See the link above for documentation on this output.</p>

<p>My version of Go is:</p>

<pre><code>$ go version
go version go1.7.1 darwin/amd64
</code></pre>

<p>From the above results, the longest wall clock STW pause time is <code>0.093 ms</code>. Great!</p>

<p>However as a sanity check I also manually timed how long it took to create a new <code>message</code> by wrapping <code>mkMessage</code> with</p>

<pre><code>start := time.Now()
m := mkMessage(highID)
elapsed := time.Since(start)
</code></pre>

<p>and printed the slowest <code>elapsed</code> time. The time I get for this was <code>38.573036ms</code>!</p>

<p>I was instantly suspicious because this correlated strongly with the wall clock times in the supposedly concurrent mark/scan phase, and in particular with "idle GC time".</p>

<p><strong>My question is: why does this supposedly concurrent phase of the GC appear to block the mutator?</strong></p>

<p>If I force the GC to run at regular intervals, my manually calculated pause times go way down to &lt;1ms, so it appears to be hitting some kind of limit of non-live heap objects. If so, I'm not sure what that limit is, and why it would cause a concurrent phase of the GC to appear to block the mutator.</p>