runtime: go1.13.5/go tip worst gc pause time increase from go1.9.7 in darwin/amd64

[bronze1man]

What version of Go are you using (go version)?

$ go version
go version go1.13.5 darwin/amd64
go version devel +7d30af8 Fri Dec 13 20:41:04 2019 +0000 darwin/amd64

Does this issue reproduce with the latest release?

yes.

What operating system and processor architecture are you using (go env)?

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/a/Library/Caches/go-build"
GOENV="/Users/a/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/a/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/m9/qtbxkp6s3p96fk54rln7qhj80000gp/T/go-build165542294=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

package main

import (
	"fmt"
	"time"
)

const (
	windowSize = 200000
	msgCount   = 1e7
)

type (
	message []byte
	buffer  [windowSize]message
)

var worst time.Duration

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

func pushMsg(b *buffer, highID int) {
	start := time.Now()
	m := mkMessage(highID)
	(*b)[highID%windowSize] = m
	_ = m
	elapsed := time.Since(start)
	if elapsed > worst {
		worst = elapsed
	}
}

func main() {
	var b buffer
	for i := 0; i < msgCount; i++ {
		pushMsg(&b, i)
	}
	fmt.Println("Worst push time: ", worst)
}

Code modified from https://making.pusher.com/golangs-real-time-gc-in-theory-and-practice/

What did you expect to see?

Worst gc pause time decrease or equal.

What did you see instead?

Worst gc pause time increase.

go version go1.9.7 darwin/amd64:
Worst push time:  9.354054ms
Worst push time:  8.229477ms
Worst push time:  7.651093ms
Worst push time:  8.560363ms

go version go1.13.5 darwin/amd64:
Worst push time:  190.080638ms
Worst push time:  15.075733ms
Worst push time:  14.391396ms
Worst push time:  14.358026ms

go version devel +7d30af8 Fri Dec 13 20:41:04 2019 +0000 darwin/amd64
Worst push time:  12.889516ms
Worst push time:  14.144591ms
Worst push time:  12.965626ms
Worst push time:  14.668102ms

[bronze1man]

all result from go1.7.6 to go1.13.5 to go tip

go version go1.7.6 darwin/amd64
Worst push time:  8.766ms
Worst push time:  8.784ms
Worst push time:  9.238ms
Worst push time:  9.174ms

go version go1.8.7 darwin/amd64
Worst push time:  10.571ms
Worst push time:  10.922ms
Worst push time:  10.465ms
Worst push time:  9.046ms

go version go1.9.7 darwin/amd64:
Worst push time:  9.354054ms
Worst push time:  8.229477ms
Worst push time:  7.651093ms
Worst push time:  8.560363ms

go version go1.10.8 darwin/amd64
Worst push time:  8.489223ms
Worst push time:  9.597068ms
Worst push time:  8.379077ms
Worst push time:  9.057248ms

go version go1.11.13 darwin/amd64
Worst push time:  8.394854ms
Worst push time:  8.581015ms
Worst push time:  9.558599ms
Worst push time:  7.980982ms
Worst push time:  11.677961ms

go version go1.12.14 darwin/amd64
Worst push time:  15.779078ms
Worst push time:  16.682774ms
Worst push time:  17.249574ms
Worst push time:  15.593871ms

go version go1.13.5 darwin/amd64:
Worst push time:  190.080638ms
Worst push time:  15.075733ms
Worst push time:  14.391396ms
Worst push time:  14.358026ms

go version devel +7d30af8 Fri Dec 13 20:41:04 2019 +0000 darwin/amd64
Worst push time:  12.889516ms
Worst push time:  14.144591ms
Worst push time:  12.965626ms
Worst push time:  14.668102ms

go1.9.7/go1.11.13 is the best.

[changkun]

a known issue introduced in 1.12 may be related, see 95a6f11

[dmitshur]

/cc @aclements @randall77 per owners.