Skip to content

x/net/http2: slow performance on Internet-latency links #17985

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Closed
yonderblue opened this issue Nov 19, 2016 · 29 comments
Closed

x/net/http2: slow performance on Internet-latency links #17985

yonderblue opened this issue Nov 19, 2016 · 29 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Go1.9

Comments

@yonderblue
Copy link

yonderblue commented Nov 19, 2016 •
edited
Loading

amd64 go1.7.3 and a vendored http2 at master.

I'm doing something a little strange and running into a performance problem.

I have a client and server. Once the client connects to the server it then starts serving itself on the connection and the server makes calls to the client, all through http2.

An example program is below but normally I am testing this between two machines over the internet and that is where things are slower than expected.
On a LAN it is very fast and if you run the program below it is 371ms or about 25MB/s which isn't bad. But over the internet even when scp between the two boxes is fast in both directions, this is still slow.

server.go

package main

import (
	"bytes"
	"crypto/tls"
	"fmt"
	"net"
	"net/http"
	"time"

	"golang.org/x/net/http2"
)

func main() {
	ln, err := net.Listen("tcp", ":8443")
	if err != nil {
		panic(err)
	}
	defer ln.Close()

	conn, err := ln.Accept()
	if err != nil {
		panic(err)
	}
	defer conn.Close()

	tlsConfig := &tls.Config{InsecureSkipVerify: true}

	tlsConn := tls.Client(conn, tlsConfig)

	if err := tlsConn.Handshake(); err != nil {
		panic(err)
	}

	t := &http2.Transport{
		TLSClientConfig: tlsConfig,
		DialTLS: func(string, string, *tls.Config) (net.Conn, error) {
			return tlsConn, nil
		},
	}

	client := &http.Client{Transport: t}

	r := bytes.NewReader(make([]byte, 10e6))

	time.Sleep(time.Second * 1)

	fmt.Println("POSTING")
	resp, err := client.Post("https://1.2.3.4/foo", "", r)
	if err != nil {
		panic(err)
	}
	defer resp.Body.Close()

	fmt.Println("DONE POSTING")
}

client.go

package main

import (
	"crypto/tls"
	"fmt"
	"io"
	"io/ioutil"
	"net"
	"net/http"
	"time"

	"golang.org/x/net/http2"
)

func consumeRequest(w http.ResponseWriter, req *http.Request) {
	fmt.Println("DISCARDING")
	now := time.Now()
	n, _ := io.Copy(ioutil.Discard, req.Body)
	fmt.Println("DONE DISCARDING", time.Now().Sub(now), n)
}

func main() {
	conn, err := net.Dial("tcp", "127.0.0.1:8443")
	if err != nil {
		panic(err)
	}
	defer conn.Close()

	tlsConn := tls.Server(conn, &tls.Config{InsecureSkipVerify: true, Certificates: []tls.Certificate{cert}})

	if err := tlsConn.Handshake(); err != nil {
		panic(err)
	}

	h2s := &http2.Server{}
	h2s.ServeConn(tlsConn, &http2.ServeConnOpts{Handler: http.HandlerFunc(consumeRequest)})
}

var cert, _ = tls.X509KeyPair(certPEM, keyPEM)

var certPEM = []byte(
	`-----BEGIN CERTIFICATE-----
MIIB0zCCAX2gAwIBAgIJAI/M7BYjwB+uMA0GCSqGSIb3DQEBBQUAMEUxCzAJBgNV
BAYTAkFVMRMwEQYDVQQIDApTb21lLVN0YXRlMSEwHwYDVQQKDBhJbnRlcm5ldCBX
aWRnaXRzIFB0eSBMdGQwHhcNMTIwOTEyMjE1MjAyWhcNMTUwOTEyMjE1MjAyWjBF
MQswCQYDVQQGEwJBVTETMBEGA1UECAwKU29tZS1TdGF0ZTEhMB8GA1UECgwYSW50
ZXJuZXQgV2lkZ2l0cyBQdHkgTHRkMFwwDQYJKoZIhvcNAQEBBQADSwAwSAJBANLJ
hPHhITqQbPklG3ibCVxwGMRfp/v4XqhfdQHdcVfHap6NQ5Wok/4xIA+ui35/MmNa
rtNuC+BdZ1tMuVCPFZcCAwEAAaNQME4wHQYDVR0OBBYEFJvKs8RfJaXTH08W+SGv
zQyKn0H8MB8GA1UdIwQYMBaAFJvKs8RfJaXTH08W+SGvzQyKn0H8MAwGA1UdEwQF
MAMBAf8wDQYJKoZIhvcNAQEFBQADQQBJlffJHybjDGxRMqaRmDhX0+6v02TUKZsW
r5QuVbpQhH6u+0UgcW0jp9QwpxoPTLTWGXEWBBBurxFwiCBhkQ+V
-----END CERTIFICATE-----`,
)
var keyPEM = []byte(
	`-----BEGIN RSA PRIVATE KEY-----
MIIBOwIBAAJBANLJhPHhITqQbPklG3ibCVxwGMRfp/v4XqhfdQHdcVfHap6NQ5Wo
k/4xIA+ui35/MmNartNuC+BdZ1tMuVCPFZcCAwEAAQJAEJ2N+zsR0Xn8/Q6twa4G
6OB1M1WO+k+ztnX/1SvNeWu8D6GImtupLTYgjZcHufykj09jiHmjHx8u8ZZB/o1N
MQIhAPW+eyZo7ay3lMz1V01WVjNKK9QSn1MJlb06h/LuYv9FAiEA25WPedKgVyCW
SmUwbPw8fnTcpqDWE3yTO3vKcebqMSsCIBF3UmVue8YU3jybC3NxuXq3wNm34R8T
xVLHwDXh/6NJAiEAl2oHGGLz64BuAfjKrqwz7qMYr9HCLIe/YsoWq/olzScCIQDi
D2lWusoe2/nEqfDVVWGWlyJ7yOmqaVm/iNUN9B2N2g==
-----END RSA PRIVATE KEY-----`,
)

It turns out that the tests from the http2 client writing into a request and the http2 server reading from the request is slow. That is despite whether the http2 server is on the server end of the tcp connection or the client end. This is between two machines with a 55ms latency. Scp is fast over the two machines in both directions. As is the test over two machines on a LAN.
I've tried changing the following constants in the http2 code, handlerChunkWriteSize, transportDefaultStreamMinRefresh, defaultMaxReadFrameSize, initialWindowSize, initialHeaderTableSize and initialMaxFrameSize to no effect.

https://groups.google.com/forum/#!topic/golang-nuts/M0gPiyAGVG0
@minux
Copy link
Member

minux commented Nov 19, 2016 via email

@minux
Copy link
Member

minux commented Nov 19, 2016 via email

@yonderblue
Copy link
Author

yonderblue commented Nov 19, 2016 •
edited
Loading

Yes it is fast, because its fast when I go from the http2 server and write to the response and read it in the http2 client resp.

Keep in mind we have done it both ways, tcp server doing http2 client on one machine and tcp client doing http2 server on the other, and completely visa versa too.

If I print some time out, it appears all the time is spent in the writeRequestBody() doing awaitFlowControl() in transport.go.

I'm looking at a slowdown where one direction goes 0.7 seconds or less (testing with 10MB) and the other 8 seconds. In that loop in transport.go the read is 0.003s, the awaitflow is 8s and the write to the stream is 0.3s and the lock taken there is only 0.0007s. But why doesn't it get more flow from the server? The handler in the server is throwing away the data it reads from the request as fast as it can.
The server appears to be waiting on frames, and the client appears to be waiting on flow. Isn't that some kind of catch 22?

@yonderblue
Copy link
Author

I updated the code example above to what reproduces the issue for me. If you run them on two machines over WAN (on a good pipe) it performs very badly. This is a serious issue for us if someone has some free time we would greatly appreciate it.

@yonderblue yonderblue changed the title slowdown in one direction on http2. major slowdown in one direction on http2. Nov 19, 2016
@yonderblue
Copy link
Author

yonderblue commented Nov 19, 2016 •
edited
Loading

Yet this program does not show the issue, and I believe I am simulating latency correctly.

combined.go

package main

import (
	"bytes"
	"crypto/tls"
	"fmt"
	"io"
	"io/ioutil"
	"net"
	"net/http"
	"time"

	"golang.org/x/net/http2"
)

const delay = time.Millisecond * 10

func main() {
	ch := make(chan struct{})
	go func() { client(); ch <- struct{}{} }()
	go func() { server(); ch <- struct{}{} }()
	<-ch
	<-ch
}

type slowConn struct {
	net.Conn
	w chan []byte
}

func (c slowConn) Read(buf []byte) (int, error) {
	return c.Conn.Read(buf)
}

func (c slowConn) writes() {
	for buf := range c.w {
		time.Sleep(delay)
		_, err := c.Conn.Write(buf)
		if err != nil {
			panic(err)
		}
	}
}

func (c slowConn) Write(buf []byte) (int, error) {
	dest := make([]byte, len(buf))
	copy(dest, buf)
	c.w <- dest
	return len(buf), nil
}

func consumeRequest(w http.ResponseWriter, req *http.Request) {
	fmt.Println("DISCARDING")
	now := time.Now()
	n, _ := io.Copy(ioutil.Discard, req.Body)
	fmt.Println("DONE DISCARDING", time.Now().Sub(now), n)
}

func client() {
	conn, err := net.Dial("tcp", "127.0.0.1:8443")
	if err != nil {
		panic(err)
	}
	defer conn.Close()

	sc := slowConn{conn, make(chan []byte)}
	go sc.writes()
	conn = sc

	tlsConn := tls.Server(conn, &tls.Config{InsecureSkipVerify: true, Certificates: []tls.Certificate{cert}})

	if err := tlsConn.Handshake(); err != nil {
		panic(err)
	}

	h2s := &http2.Server{}
	h2s.ServeConn(tlsConn, &http2.ServeConnOpts{Handler: http.HandlerFunc(consumeRequest)})
}

func server() {
	ln, err := net.Listen("tcp", ":8443")
	if err != nil {
		panic(err)
	}
	defer ln.Close()

	conn, err := ln.Accept()
	if err != nil {
		panic(err)
	}
	defer conn.Close()

	sc := slowConn{conn, make(chan []byte)}
	go sc.writes()
	conn = sc

	tlsConfig := &tls.Config{InsecureSkipVerify: true}

	tlsConn := tls.Client(conn, tlsConfig)

	if err := tlsConn.Handshake(); err != nil {
		panic(err)
	}

	t := &http2.Transport{
		TLSClientConfig: tlsConfig,
		DialTLS: func(string, string, *tls.Config) (net.Conn, error) {
			return tlsConn, nil
		},
	}

	client := &http.Client{Transport: t}

	time.Sleep(time.Second * 1)

	r := bytes.NewReader(make([]byte, 10e6))

	fmt.Println("POSTING")
	resp, err := client.Post("https://1.2.3.4/foo", "", r)
	if err != nil {
		panic(err)
	}
	defer resp.Body.Close()

	fmt.Println("DONE POSTING")
}

var cert, _ = tls.X509KeyPair(certPEM, keyPEM)

var certPEM = []byte(
	`-----BEGIN CERTIFICATE-----
MIIB0zCCAX2gAwIBAgIJAI/M7BYjwB+uMA0GCSqGSIb3DQEBBQUAMEUxCzAJBgNV
BAYTAkFVMRMwEQYDVQQIDApTb21lLVN0YXRlMSEwHwYDVQQKDBhJbnRlcm5ldCBX
aWRnaXRzIFB0eSBMdGQwHhcNMTIwOTEyMjE1MjAyWhcNMTUwOTEyMjE1MjAyWjBF
MQswCQYDVQQGEwJBVTETMBEGA1UECAwKU29tZS1TdGF0ZTEhMB8GA1UECgwYSW50
ZXJuZXQgV2lkZ2l0cyBQdHkgTHRkMFwwDQYJKoZIhvcNAQEBBQADSwAwSAJBANLJ
hPHhITqQbPklG3ibCVxwGMRfp/v4XqhfdQHdcVfHap6NQ5Wok/4xIA+ui35/MmNa
rtNuC+BdZ1tMuVCPFZcCAwEAAaNQME4wHQYDVR0OBBYEFJvKs8RfJaXTH08W+SGv
zQyKn0H8MB8GA1UdIwQYMBaAFJvKs8RfJaXTH08W+SGvzQyKn0H8MAwGA1UdEwQF
MAMBAf8wDQYJKoZIhvcNAQEFBQADQQBJlffJHybjDGxRMqaRmDhX0+6v02TUKZsW
r5QuVbpQhH6u+0UgcW0jp9QwpxoPTLTWGXEWBBBurxFwiCBhkQ+V
-----END CERTIFICATE-----`,
)
var keyPEM = []byte(
	`-----BEGIN RSA PRIVATE KEY-----
MIIBOwIBAAJBANLJhPHhITqQbPklG3ibCVxwGMRfp/v4XqhfdQHdcVfHap6NQ5Wo
k/4xIA+ui35/MmNartNuC+BdZ1tMuVCPFZcCAwEAAQJAEJ2N+zsR0Xn8/Q6twa4G
6OB1M1WO+k+ztnX/1SvNeWu8D6GImtupLTYgjZcHufykj09jiHmjHx8u8ZZB/o1N
MQIhAPW+eyZo7ay3lMz1V01WVjNKK9QSn1MJlb06h/LuYv9FAiEA25WPedKgVyCW
SmUwbPw8fnTcpqDWE3yTO3vKcebqMSsCIBF3UmVue8YU3jybC3NxuXq3wNm34R8T
xVLHwDXh/6NJAiEAl2oHGGLz64BuAfjKrqwz7qMYr9HCLIe/YsoWq/olzScCIQDi
D2lWusoe2/nEqfDVVWGWlyJ7yOmqaVm/iNUN9B2N2g==
-----END RSA PRIVATE KEY-----`,
)

@yonderblue
Copy link
Author

Here is a bit in the middle of the GODEBUG=http2debug=1

server.go

2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=8192
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=8161
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=8192
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=8161
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=3
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=3
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=8192
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=8192
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=8192
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=8188
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=8192
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=8192
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=8192
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=8188
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=8192
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=8158
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=8192
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=8158
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=8192
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=8160
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=8192
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=8160
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=5
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=5
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=8192
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=8192
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=8192
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=8192
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=8192
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=8189
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=8192
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=8189
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=8192
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=8159
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=8192
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=8159
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=1
2016/11/20 00:22:58 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=1

client.go

2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=16384 data="\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00" (16128 bytes omitted)
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=16382 data="\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00" (16126 bytes omitted)
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=16349 data="\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00" (16093 bytes omitted)
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=3 data="\x00\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=16352 data="\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00" (16096 bytes omitted)
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=3 data="\x00\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=16383 data="\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00" (16127 bytes omitted)
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=16382 data="\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00" (16126 bytes omitted)
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=16349 data="\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00" (16093 bytes omitted)
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=3 data="\x00\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=16353 data="\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00" (16097 bytes omitted)
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=3 data="\x00\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=16384 data="\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00" (16128 bytes omitted)
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=16382 data="\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00" (16126 bytes omitted)
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=16350 data="\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00" (16094 bytes omitted)
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=3 data="\x00\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=16352 data="\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00" (16096 bytes omitted)
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=3 data="\x00\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=16383 data="\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00" (16127 bytes omitted)
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=16383 data="\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00" (16127 bytes omitted)
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=16349 data="\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00" (16093 bytes omitted)
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=3 data="\x00\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=2 data="\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=3 data="\x00\x00\x00"
2016/11/19 16:23:55 http2: server read frame DATA stream=1 len=1 data="\x00"

Seems like a lot of window updates of 1 or 2 and a lot of transmissions of 1 or 2 bytes??

@yonderblue
Copy link
Author

Can I poke for some attention? :)

@nussjustin
Copy link
Contributor

Maybe @bradfitz can find some time to look into this.

I took a short look at this, but couldn't reproduce it. As far as I understand the http2 server code the server (client.go) will send a window update everytime it reads from the request with the same window size as the number of bytes read (in my case always 8192, which is probably just the length of the slice passed to the io.Reader). I haven't looked at the client side (server.go) yet, as I don't currently have that much time.

@yonderblue
Copy link
Author

yonderblue commented Nov 22, 2016 •
edited
Loading

We have tested this on a number of different networks all with very high speeds (> 12MB/s both ways) and the problem persist with the above client.go and server.go where we get a max of 2 MBs.

@yonderblue
Copy link
Author

Isn't the fact that the exact write size is returned in a window update by the server when it reads mean that it ping pongs and is at the whim of latency? I have tried to make some edits to send an arbitrarily large window update to diagnose but I kept getting some errors since the code doesn't expect that. I also have that combined.go above that simulated latency and it doesn't show an issue.

@quentinmit quentinmit added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Nov 22, 2016
@quentinmit quentinmit added this to the Go1.8Maybe milestone Nov 22, 2016
@quentinmit quentinmit changed the title major slowdown in one direction on http2. x/net/http2: slow performance on Internet-latency links Nov 22, 2016
@bradfitz
Copy link
Contributor

This seems like a fun mystery, but I don't have time to investigate this before family turkey time. And Go 1.8 (or betas of it) are coming soon, so it seems unlikely we can fix it by then.

I'll retarget this to Go 1.9, but it could be fixed outside of a release sooner (in x/net).

Maybe related: #16512
Less likely related: #16498

What would be motivating would be a self-contained unit test (or program) that exhibited the problem, listening on "127.0.0.1:0" and such, picking free ports, so the program (or test) always worked. A test is probably best, since we'd need one in the fix later anyway.

/cc @tombergan

@bradfitz bradfitz modified the milestones: Go1.9, Go1.8Maybe Nov 23, 2016
@tombergan
Copy link
Contributor

tombergan commented Nov 23, 2016 •
edited
Loading

As a sanity check, can you run the same program with http1 instead of http2 (note GODEBUG=http2client=0,http2server=0) and report the execution times for both http1 and http2? (It's helpful if you can report these times in bytes/sec.)

This is between two machines with a 55ms latency.

What is the expected bandwidth of this link?

Seems like a lot of window updates of 1 or 2 and a lot of transmissions of 1 or 2 bytes??

Breaking down the tower of buffers:

The http2 server copies the request body into ioutil.Discard. Each successful Read during this copy generates a window update. The copy uses an 8KB byte buffer, which explains why the server (generally) sends 8192 byte window updates. However, when the server's http handler reads from resp.Body, it actually reads from a fixed buffer of size 65535 bytes. This is the server's receive window size. Note that 8KB doesn't divide evenly into 65535 -- this explains why we sometimes see small WINDOW_UPDATEs. Small WINDOW_UPDATEs are not necessarily a bad thing, as long as we can send a whole bunch of them in sequence.

The problem is almost certainly #16512, at least in part. You didn't state the bandwidth of your connection. If we assume 10Mbit/sec at 55ms latency, the BDP is ~68KB (slightly higher than the server's 64KB window). If we assume 100Mbit/sec at 55ms latency, the BDP is ~680KB (much higher than the server's receive window).

Can you also try running with the following patch? (warning: not tested)

diff --git a/http2/server.go b/http2/server.go
index 0b6b4b0..eeafa01 100644
--- a/http2/server.go
+++ b/http2/server.go
@@ -50,10 +50,11 @@ import (
 )
 
 const (
-       prefaceTimeout        = 10 * time.Second
-       firstSettingsTimeout  = 2 * time.Second // should be in-flight with preface anyway
-       handlerChunkWriteSize = 4 << 10
-       defaultMaxStreams     = 250 // TODO: make this 100 as the GFE seems to?
+       prefaceTimeout          = 10 * time.Second
+       firstSettingsTimeout    = 2 * time.Second // should be in-flight with preface anyway
+       handlerChunkWriteSize   = 4 << 10
+       defaultMaxStreams       = 250     // TODO: make this 100 as the GFE seems to?
+       serverInitialWindowSize = 1 << 30 // 1GB for testing
 )
 
 var (
@@ -285,7 +286,7 @@ func (s *Server) ServeConn(c net.Conn, opts *ServeConnOpts) {
        }
 
        sc.flow.add(initialWindowSize)
-       sc.inflow.add(initialWindowSize)
+       sc.inflow.add(serverInitialWindowSize)
        sc.hpackEncoder = hpack.NewEncoder(&sc.headerWriteBuf)
 
        fr := NewFramer(sc.bw, c)
@@ -687,6 +688,7 @@ func (sc *serverConn) serve() {
                        // SettingInitialWindowSize, but then we also
                        // want to bump up the conn window size the
                        // same amount here right after the settings
+                       {SettingInitialWindowSize, serverInitialWindowSize},
                },
        })
        sc.unackedSettings++
@@ -1671,8 +1673,8 @@ func (sc *serverConn) newStream(id, pusherID uint32, state streamState) *stream
        st.cw.Init()
        st.flow.conn = &sc.flow // link to conn-level counter
        st.flow.add(sc.initialWindowSize)
-       st.inflow.conn = &sc.inflow      // link to conn-level counter
-       st.inflow.add(initialWindowSize) // TODO: update this when we send a higher initial window size in the initial settings
+       st.inflow.conn = &sc.inflow            // link to conn-level counter
+       st.inflow.add(serverInitialWindowSize) // TODO: update this when we send a higher initial window size in the initial settings
        sc.streams[id] = st
        sc.writeSched.OpenStream(st.id, OpenStreamOptions{PusherID: pusherID})

@yonderblue
Copy link
Author

yonderblue commented Dec 1, 2016 •
edited
Loading

@tombergan I tried the changes, no affect. The time I am capturing for my client.go is timing f, err := sc.framer.ReadFrame() in http2/server.go is where all 8.5s are going. And in my server.go its all in allowed, err = cs.awaitFlowControl(len(remain)) in transport.go, same time 8.5s.
Latency between these boxes is 55ms according to ping. Bandwidth between the two in both directions is easily over 10MBs.
Do you have any idea why my combined.go doesn't reproduce the issue on one machine?

@tombergan
Copy link
Contributor

I do not know what's happening. Can you run the same experiment with both http1 and http2 and report the upload speed you see in both cases? We should verify the problem is actually in http2 and not a lower layer.

@yonderblue
Copy link
Author

yonderblue commented Dec 2, 2016 •
edited
Loading

If I do just a straight ListenAndServe in my server.go and a POST with the 10MB body in my client.go and discard in server.go, it is completing in 1.8s so > 5MBs.
In the code above that uses http2 it ends up being 8.5ish secs, so a little over 1MBs.

@yonderblue
Copy link
Author

yonderblue commented Dec 2, 2016 •
edited
Loading

So if I take your changes, put a 1 second sleep and log in front of the sc.writeFrame(frameWriteMsg{ in http2/server.go as well as log before the f.w.Write(f.wbuf) in http2/frame.go, what I see is my client.go writing window updates of 8k but it takes 4 of them for stream 1 (stream 0 is also writing) so it takes 8 window updates before I see them actually written out in http2/frame.go. Only when that happens do I see more data written in my server.go, which then sits waiting for 8 window updates. Of course I have that sleep to see this so not sure if that helps you?

It seems correct however is very different when I remove the sleep. I know you said the bunches of small window updates is not harmful, but that is clearly what it is waiting on as they multiply tons compared to the version with the sleep and correspond with the framer writers.

Is there a way to line these buffers up to eliminates the 1's and 2's?

@yonderblue
Copy link
Author

yonderblue commented Dec 2, 2016 •
edited
Loading

ah! First time I have seen it fast. 569ms. So with your changes and just hacking in 16000 or so at b.conn.noteBodyReadFromHandler(b.stream, 16000) for the requestBody Read() in http2/server.go.

Sometimes it fails with Post https://1.2.3.4/foo: stream error: stream ID 1; STREAM_CLOSED in my server.go but when it completes its fast and does transmit the whole 10MB.

@tombergan
Copy link
Contributor

tombergan commented Dec 2, 2016 •
edited
Loading

If I do just a straight ListenAndServe in my server.go and a POST with the 10MB body in my client.go and discard in server.go, it is completing in 1.8s so > 5MBs. In the code above that uses http2 it ends up being 8.5ish secs, so a little over 1MBs.

You see 4.7x faster performance with http1 than http2. Your expected bandwidth is about 5.55MB/s, and latency is 55ms, so the BDP of this link is about 320KB, which is ~4.9x bigger than the default flow window of 64KB. This means the performance difference can be entirely explained by a low flow control window. For some reason, my above patch did not successfully increase the flow window from 64KB to 1GB.

I think I figured out the problem. In the patch above, I forgot that SettingInitialWindowSize applies to stream-level flow control only; it leaves the connection flow window at 64KB. What if you use my patch above (and nothing else) and also add the following to serverConn.serve()?

  // At line 694, just before the call to sc.readPreface()
  sc.sendWindowUpdate(nil, serverInitialWindowSize)

If this works, I will be convinced that this bug is a dup of #16512. Brad and I will chat at some point about the best way to fix this more permanently.

@yonderblue
Copy link
Author

yonderblue commented Dec 2, 2016 •
edited
Loading

@tombergan Yes if I make that change it is fast, however it required one extra change to comment out panic("internal error; sent too many window updates without decrements?") which otherwise is always hit. Also with the change most of the time I get Post https://1.2.3.4/foo: stream error: stream ID 1; STREAM_CLOSED in my server.go and sometimes DONE DISCARDING 487.024094ms 3309567 from my client.go however if I run it enough times eventually I do see DONE DISCARDING 583.319288ms 10000000 in my client.go and no error in my server.go.

This represents a 16X (!) difference from a pretty consistent 1.1MB/s to a 17MBs on this specific server, other servers will be even bigger.
A believed to be safe edit I could make even before an official fix would be highly appreciated.

@yonderblue
Copy link
Author

yonderblue commented Dec 2, 2016 •
edited
Loading

@tombergan

With your last change I have to comment out sc.inflow.add(serverInitialWindowSize) in ServeConn() to get rid of the panic.

Still have the STREAM_CLOSED issue though above. It comes out at the bottom of the if statement if !ok || st.state != stateOpen || st.gotTrailerHeader { in processData(). Any idea what causes that with only a flow control change?
Looks like in serverConn.processFrame()'s goroutine the stream is reset because of a peer frame, which removes from the serverConn streams map immediately. However the serverConn.processData() needs it to be able to feed the handler's reader which might not be done which is in another goroutine, so we get this stream closed error.

@tombergan
Copy link
Contributor

D'oh. Sorry for all the bugs. This is what I get for trying to program in github comments. I think that should have been:

  sc.sendWindowUpdate(nil, serverInitialWindowSize - initialWindowSize)

There may still be more bugs ... I haven't had time to patch in the change myself.

@yonderblue
Copy link
Author

yonderblue commented Dec 7, 2016 •
edited
Loading

I get the same error with that :(

#16481 seems to be very similar to my error?

@yonderblue
Copy link
Author

Any idea when this would get worked on the dev cycle since a commit in the net repo could be used as soon as its ready?

@tombergan tombergan self-assigned this Dec 20, 2016
@tombergan
Copy link
Contributor

I will try to get to this in the first couple weeks of January. Can you verify that the programs in the original comment compile against go 1.8 and exhibit the problem? Thanks.

@tombergan tombergan mentioned this issue Dec 21, 2016
Closed
@yonderblue
Copy link
Author

Using this patch https://go-review.googlesource.com/#/c/35118/ and the rest of the http2 pkg at that commit and setting InitialWindowSize to 10 megs or higher resulted in a 6.7s time versus 10.6s without. This is the same test as above.

@yonderblue
Copy link
Author

Any loving care here? :)

@gopherbot
Copy link
Contributor

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

gopherbot pushed a commit to golang/net that referenced this issue Feb 27, 2017
@tombergan @bradfitz
http2: add configurable knobs for the server's receive window
906cda9 
Upload performance is poor when BDP is higher than the flow-control window.
Previously, the server's receive window was fixed at 64KB, which resulted in
very poor performance for high-BDP links. The receive window now defaults to
1MB and is configurable. The per-connection and per-stream windows are
configurable separately (both default to 1MB as suggested in golang/go#16512).

Previously, the server created a "fixedBuffer" for each request body. This is no
longer a good idea because a fixedBuffer has fixed size, which means individual
streams cannot use varying amounts of the available connection window. To
overcome this limitation, I replaced fixedBuffer with "dataBuffer", which grows
and shrinks based on current usage. The worst-case fragmentation of dataBuffer
is 32KB wasted memory per stream, but I expect that worst-case will be rare.

A slightly modified version of adg@'s grpcbench program shows a dramatic
improvement when increasing from a 64KB window to a 1MB window, especially at
higher latencies (i.e., higher BDPs). Network latency was simulated with netem,
e.g., `tc qdisc add dev lo root netem delay 16ms`.

Duration        Latency Proto           H2 Window

11ms±4.05ms     0s      HTTP/1.1        -
17ms±1.95ms     0s      HTTP/2.0        65535
8ms±1.75ms      0s      HTTP/2.0        1048576

10ms±1.49ms     1ms     HTTP/1.1        -
47ms±2.91ms     1ms     HTTP/2.0        65535
10ms±1.77ms     1ms     HTTP/2.0        1048576

15ms±1.69ms     2ms     HTTP/1.1        -
88ms±11.29ms    2ms     HTTP/2.0        65535
15ms±1.18ms     2ms     HTTP/2.0        1048576

23ms±1.42ms     4ms     HTTP/1.1        -
152ms±0.77ms    4ms     HTTP/2.0        65535
23ms±0.94ms     4ms     HTTP/2.0        1048576

40ms±1.54ms     8ms     HTTP/1.1        -
288ms±1.67ms    8ms     HTTP/2.0        65535
39ms±1.29ms     8ms     HTTP/2.0        1048576

72ms±1.13ms     16ms    HTTP/1.1        -
559ms±0.68ms    16ms    HTTP/2.0        65535
71ms±1.12ms     16ms    HTTP/2.0        1048576

136ms±1.15ms    32ms    HTTP/1.1        -
1104ms±1.62ms   32ms    HTTP/2.0        65535
135ms±0.96ms    32ms    HTTP/2.0        1048576

264ms±0.95ms    64ms    HTTP/1.1        -
2191ms±2.08ms   64ms    HTTP/2.0        65535
263ms±1.57ms    64ms    HTTP/2.0        1048576

Fixes golang/go#16512
Updates golang/go#17985
Updates golang/go#18404

Change-Id: Ied385aa94588337e98dad9475cf2ece2f39ba346
Reviewed-on: https://go-review.googlesource.com/37226
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
@tombergan
Copy link
Contributor

@Gaillard I believe this is fixed. Please report back if not.

@yonderblue
Copy link
Author

Yup issue fixed :D Thanks guys!

@golang golang locked and limited conversation to collaborators Feb 27, 2018
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Milestone
Go1.9
Development

No branches or pull requests
7 participants
@bradfitz @quentinmit @minux @yonderblue @nussjustin @gopherbot @tombergan