runtime: GC pause on Go 1.5 is much longer than Go 1.4 when there is a map with lots of entries.

[coocood]

Go version is 1.4.2 and Go devel +80864cf Fri May 29 04:33:15 2015 +0000.
OS is linux/amd64.

GC pause time is about 600ms on Go 1.5 and 300ms on Go 1.4.

Sample code to test GC pause time.

package main

import (
    "fmt"
    "runtime"
    "runtime/debug"
    "time"
)

func GCPause() time.Duration {
    runtime.GC()
    var stats debug.GCStats
    debug.ReadGCStats(&stats)
    return stats.Pause[0]
}

func main() {
    n := 3000 * 1000
    m := make(map[string][]byte)
    for i := 0; i < n; i++ {
        key := fmt.Sprintf("key%v", i)
        val := make([]byte, 10)
        m[key] = val
    }
    fmt.Println("GC pause with 3 million map entries:", GCPause())
}

[ianlancetaylor]

@RLH @aclements

[RLH]

runtime.GC() does not do a concurrent GC, it does a STW GC which accounts
for the pause the program is printing.

Below is the same program that prints out some diagnostics, there are 14
GCs, 13 are concurrent and one is not. The (forced) at the end of the last
diagnostic message indicating a call to runtime.GC() to do a STW GC. This
is the pause the program prints out. The STW pauses are the first and last
numbers of the ms clock numbers. These are truncated ints so 0 means all
STW pauses in the first 13 GCs, the concurrent ones, are < 1 millisecond.

.rlh@rlh0:~/work/code/bugs/latency1/src$ ./latency

gc #1 @0.038s 9%: 0+0+0+3+0 ms clock, 0+0+0+0/3/0+0 ms cpu, 4->7->3
MB, 4 MB goal, 1 P
gc #2 @0.048s 17%: 0+0+0+4+0 ms clock, 0+0+0+0/4/0+0 ms cpu, 4->4->4
MB, 7 MB goal, 1 P
gc #3 @0.062s 27%: 0+0+0+8+0 ms clock, 0+0+0+0/8/0+0 ms cpu, 6->10->10
MB, 8 MB goal, 1 P
gc #4 @0.104s 27%: 0+0+0+11+0 ms clock, 0+0+0+0/11/0+0 ms cpu,
13->13->9 MB, 20 MB goal, 1 P
gc #5 @0.125s 36%: 0+0+0+17+0 ms clock, 0+0+0+0/17/0+0 ms cpu,
15->20->20 MB, 18 MB goal, 1 P
gc #6 @0.296s 30%: 0+0+0+102+0 ms clock, 0+0+0+22/21/0+0 ms cpu,
32->48->40 MB, 40 MB goal, 1 P
gc #7 @0.489s 25%: 0+0+0+149+0 ms clock, 0+0+0+0/34/0+0 ms cpu,
41->47->34 MB, 80 MB goal, 1 P
gc #8 @0.739s 29%: 0+0+0+197+0 ms clock, 0+0+0+43/47/0+0 ms cpu,
42->84->81 MB, 58 MB goal, 1 P
gc #9 @1.123s 27%: 0+0+0+379+0 ms clock, 0+0+0+0/91/0+0 ms cpu,
80->87->85 MB, 161 MB goal, 1 P
gc #10 @1.615s 30%: 0+0+0+321+0 ms clock, 0+0+0+80/104/0+0 ms cpu,
116->192->162 MB, 158 MB goal, 1 P
gc #11 @2.442s 28%: 0+0+0+818+0 ms clock, 0+0+0+0/201/0+0 ms cpu,
161->171->169 MB, 322 MB goal, 1 P
gc #12 @3.356s 32%: 0+0+0+539+0 ms clock, 0+0+0+154/238/0+0 ms cpu,
234->385->323 MB, 319 MB goal, 1 P
gc #13 @5.241s 29%: 0+0+0+1867+0 ms clock, 0+0+0+0/465/0+0 ms cpu,
322->344->341 MB, 644 MB goal, 1 P
gc #14 @6.311s 40%: 0+0+0+0+568 ms clock, 0+0+0+0/465/0+568 ms cpu,
401->401->281 MB, 401 MB goal, 1 P (forced)
GC pause with 3 million map entries: 540.676752ms
rlh@rlh0:~/work/code/bugs/latency1/src$

On Fri, May 29, 2015 at 10:30 AM, Ian Lance Taylor <[email protected]

wrote:

@RLH https:/RLH @aclements https:/aclements

—
Reply to this email directly or view it on GitHub
#10986 (comment).

[aclements]

Just a minor addition: stats.Pause doesn't accurately reflect the pause times of concurrent GCs right now, though it will be accurate for the forced STW GC that this test program is doing. Currently the only way to get accurate pause times for concurrent GCs is setting GODEBUG=gctrace=1 (which is what @RLH did). The issue with GCStats.Pause is #10323.

Perhaps runtime.GC needs documentation explaining that it does a STW GC?

[gopherbot]

CL https://golang.org/cl/10488 mentions this issue.