Serializable range performance regression with Go 1.7.3

[gyuho]

Reiterated from #6010

---

How to reproduce

Build etcd binaries, others

Build etcd binaries in different Go versions with faeeb2f

mkdir -p ${GOPATH}/src/github.com/coreos
cd ${GOPATH}/src/github.com/coreos
git clone https://github.com/coreos/etcd.git
cd ${GOPATH}/src/github.com/coreos/etcd
git reset --hard faeeb2fc7514c5caf7a9a0cc03ac9ee2ff94438b

./build
./bin/etcd --version

go build -v ./cmd/tools/benchmark
./benchmark help

Or

wget https://storage.googleapis.com/etcd/tip/etcd-v3.0.2-go1.6.3
wget https://storage.googleapis.com/etcd/tip/etcd-v3.0.2-go1.7.3
wget https://storage.googleapis.com/etcd/tip/etcdctl-master-go1.7.3
wget https://storage.googleapis.com/etcd/tip/benchmark-master-go1.7.3

sudo chmod +x ./etcd-v3.0.2-go1.6.3      && ./etcd-v3.0.2-go1.6.3 --version
sudo chmod +x ./etcd-v3.0.2-go1.7.3      && ./etcd-v3.0.2-go1.7.3 --version
sudo chmod +x ./etcdctl-master-go1.7.3   && ./etcdctl-master-go1.7.3 --version
sudo chmod +x ./benchmark-master-go1.7.3 && ./benchmark-master-go1.7.3 help

Run single-node cluster, benchmark, pprof

Go 1.6.3 + master branch Go 1.7.3 client

rm -rf test.etcd
./etcd-v3.0.2-go1.6.3 --name test \
    --listen-client-urls http://localhost:2379 \
    --advertise-client-urls http://localhost:2379 \
    --listen-peer-urls http://localhost:2380 \
    --initial-advertise-peer-urls http://localhost:2380 \
    --initial-cluster test=http://localhost:2380 \
    --initial-cluster-token test-token \
    --initial-cluster-state new \
    --enable-pprof

ETCDCTL_API=3 ./etcdctl-master-go1.7.3 --endpoints=localhost:2379 put foo bar
ETCDCTL_API=3 ./etcdctl-master-go1.7.3 --endpoints=localhost:2379 get foo --consistency=s
./benchmark-master-go1.7.3 --endpoints=localhost:2379 --conns=100 --clients=1000 range foo --consistency=s --total=2000000


rm -rf $HOME/etcd-v3.0.2-go1.6.3-2M-serializable-reads-00
mkdir -p $HOME/etcd-v3.0.2-go1.6.3-2M-serializable-reads-00
export PPROF_TMPDIR=$HOME/etcd-v3.0.2-go1.6.3-2M-serializable-reads-00
go tool pprof -seconds=50 http://localhost:2379/debug/pprof/profile

cd etcd-v3.0.2-go1.6.3-2M-serializable-reads-00/
go tool pprof -pdf ~/etcd-v3.0.2-go1.6.3 pprof.localhost\:2379.samples.cpu.001.pb.gz > etcd-v3.0.2-go1.6.3-2M-serializable-reads-00.pdf
go tool pprof -svg ~/etcd-v3.0.2-go1.6.3 pprof.localhost\:2379.samples.cpu.001.pb.gz > etcd-v3.0.2-go1.6.3-2M-serializable-reads-00.svg

Go 1.7.3 + master branch Go 1.7.3 client

rm -rf test.etcd
./etcd-v3.0.2-go1.7.3 --name test \
    --listen-client-urls http://localhost:2379 \
    --advertise-client-urls http://localhost:2379 \
    --listen-peer-urls http://localhost:2380 \
    --initial-advertise-peer-urls http://localhost:2380 \
    --initial-cluster test=http://localhost:2380 \
    --initial-cluster-token test-token \
    --initial-cluster-state new \
    --enable-pprof

ETCDCTL_API=3 ./etcdctl-master-go1.7.3 --endpoints=localhost:2379 put foo bar
ETCDCTL_API=3 ./etcdctl-master-go1.7.3 --endpoints=localhost:2379 get foo --consistency=s
./benchmark-master-go1.7.3 --endpoints=localhost:2379 --conns=100 --clients=1000 range foo --consistency=s --total=2000000


rm -rf $HOME/etcd-v3.0.2-go1.7.3-2M-serializable-reads-00
mkdir -p $HOME/etcd-v3.0.2-go1.7.3-2M-serializable-reads-00
export PPROF_TMPDIR=$HOME/etcd-v3.0.2-go1.7.3-2M-serializable-reads-00
go tool pprof -seconds=100 http://localhost:2379/debug/pprof/profile

cd etcd-v3.0.2-go1.7.3-2M-serializable-reads-00/
go tool pprof -pdf ~/etcd-v3.0.2-go1.7.3 pprof.etcd-v3.0.2-go1.7.3.localhost\:2379.samples.cpu.001.pb.gz > etcd-v3.0.2-go1.7.3-2M-serializable-reads-00.pdf
go tool pprof -svg ~/etcd-v3.0.2-go1.7.3 pprof.etcd-v3.0.2-go1.7.3.localhost\:2379.samples.cpu.001.pb.gz > etcd-v3.0.2-go1.7.3-2M-serializable-reads-00.svg

---

Update 3PM, November 21, 2016

So far we know that regression happens between Go 1.6.3 and Go 1.7.3 with etcd v3.0.2 commit faeeb2f (before gRPC bump up)

Go 1.6.3 + v3.0.2, client Go 1.7.3 master branch

Summary:
  Total:	55.4612 secs.
  Requests/sec:	36061.2548

etcd-v3.0.2-go1.6.3-2M-serializable-reads-00.pdf
pprof.localhost:2379.samples.cpu.001.pb.gz

Go 1.7.3 + v3.0.2, client Go 1.7.3 master branch

Summary:
  Total:	105.3251 secs.
  Requests/sec:	18988.8279

etcd-v3.0.2-go1.7.3-2M-serializable-reads-00.pdf
pprof.etcd-v3.0.2-go1.7.3.localhost:2379.samples.cpu.001.pb.gz

Go 1.7.3 is slow, and Go versions in benchmark does not seem to matter. I tried Go 1.7.3 + v3.0.2 with cmux disabled, but still Go 1.7.3 is much slower (Requests/sec: 18458.3038)

func serve(sctx *serveCtx, s *etcdserver.EtcdServer, tlscfg *tls.Config, handler http.Handler) error {
	<-s.ReadyNotify()
	plog.Info("ready to serve client requests")

	gs := v3rpc.Server(s, nil)
	plog.Noticef("serving insecure client requests on %s, this is strongly discouraged!", sctx.host)
	return gs.Serve(sctx.l)
}

Go 1.7.3's http2.ReadFrame calls http2.readFrameHeader, while Go 1.6.3 doesn't.

Go 1.6.3

Go 1.7.3

[gyuho]

I notice our http2 in golang.org/x/net is pretty outdated; it uses golang/net@6acef71.

Will try with latest version.

---

Update 2PM, Nov 22, 2016

etcd master branch with Go 1.6.3 shows same slow performance, so there must be something else...

Summary:
  Total:	9.2796 secs.
  Slowest:	0.6463 secs.
  Fastest:	0.0001 secs.
  Average:	0.0461 secs.
  Stddev:	0.0562 secs.
  Requests/sec:	21552.6492

---

Update 1PM, Nov 22, 2016

pprof data with same duration 30-second:

./benchmark-master-go1.7.3 --endpoints=localhost:2379 --conns=100 --clients=1000 range foo --consistency=s --total=2000000

# Go 1.6.3
  Total:	55.5685 secs.
  Requests/sec:	35991.5985

# Go 1.7.3
Summary:
  Total:	105.6422 secs.
  Requests/sec:	18931.8332

Go 1.6.3

wget https://storage.googleapis.com/etcd/tip/etcd-v3.0.2-go1.6.3
etcd-v3.0.2-go1.6.3-serializable-reads-00.pdf
pprof.localhost:2379.samples.cpu.001.pb.gz

Go 1.7.3

wget https://storage.googleapis.com/etcd/tip/etcd-v3.0.2-go1.7.3
etcd-v3.0.2-go1.7.3-serializable-reads-00.pdf
pprof.etcd-v3.0.2-go1.7.3.localhost:2379.samples.cpu.001.pb.gz

---

Update 9AM, Nov 22, 2016

Tried with latest golang.org/x/net golang/net@4971afd, but doesn't seem to help

Go 1.6.3 with old 'golang.org/x/net'

Summary:
  Requests/sec:	42126.9380

Go 1.6.3 with latest 'golang.org/x/net'

Summary:
  Requests/sec:	40994.4633

Go 1.7.3 with latest 'golang.org/x/net'

Summary:
  Requests/sec:	19959.7401

[xiang90]

we confirmed the root cause is #7083. So closing this one.