x/net/http2: unexpected read data latency

[liugangnhm]

Please answer these questions before submitting your issue. Thanks!

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

go1.9.2

I tried go1.8.2 also.

Does this issue reproduce with the latest release?

yes

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

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="my go path"
GORACE=""
GOROOT="my go root"
GOTOOLDIR="/home/liugang/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build282815162=/tmp/go-build -gno-record-gcc-switches"
CXX="g++"
CGO_ENABLED="1"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"

What did you do?

I used linux tc to simulate an network latency of 2s(receive data had no latency, and send did ) at a grpc server( etcd indeed), and I recorded the http2 debug output.

• client output

2016-12-21 05:20:21.610052
2016-12-21 05:20:23.624350 I | http2: Framer 0xc420266000: wrote SETTINGS len=0
2016-12-21 05:20:23.624518 I | http2: Framer 0xc420266000: wrote WINDOW_UPDATE len=4 (conn) incr=983025
2016-12-21 05:20:23.624743 I | http2: Framer 0xc420266000: wrote HEADERS flags=END_HEADERS stream=1 len=84
2016-12-21 05:20:23.624805 I | http2: Framer 0xc420266000: wrote DATA flags=END_STREAM stream=1 len=13 data="\x00\x00\x00\x00\b\n\x02/a\x12\x02/b"























2016-12-21 05:20:25.624685 I | http2: Framer 0xc420266000: read SETTINGS len=6, settings: MAX_CONCURRENT_STREAMS=4294967295
2016-12-21 05:20:25.624726 I | http2: Framer 0xc420266000: wrote SETTINGS flags=ACK len=0






2016-12-21 05:20:27.624661 I | http2: Framer 0xc420266000: read WINDOW_UPDATE len=4 (conn) incr=983025
2016-12-21 05:20:27.624685 I | http2: Framer 0xc420266000: read SETTINGS flags=ACK len=0
2016-12-21 05:20:27.626447 I | http2: Framer 0xc420266000: read HEADERS flags=END_HEADERS stream=1 len=142016-12-21 05:20:27.626534 I | http2: decoded hpack field header field ":status" = "200"
2016-12-21 05:20:27.626594 I | http2: decoded hpack field header field "content-type" = "application/grpc"




2016-12-21 05:20:29.626574 I | http2: Framer 0xc420266000: read DATA stream=1 len=52 data="\x00\x00\x00\x00/\n\x1a\b\x8f\xb7\x82\xaa\xbc\xa6\xb4\xa1N\x10\xb3\xbc\x99\x82\xf0Ӎ\xce\xda\x01\x18\xf5\" \x14\x12\x0f\n\x02/a\x10\xba\x1f\x18\xbb\x1f \x02*\x01b \x01"
2016-12-21 05:20:29.626607 I | http2: Framer 0xc420266000: read HEADERS flags=END_STREAM|END_HEADERS stream=1 len=24
2016-12-21 05:20:29.626627 I | http2: decoded hpack field header field "grpc-status" = "0"
2016-12-21 05:20:29.626648 I | http2: decoded hpack field header field "grpc-message" = ""

• server output

2016-12-21 05:20:23.624471 [frame.go:388] I | http2: Framer 0xc4208061c0: wrote SETTINGS len=6, settings: MAX_CONCURRENT_STREAMS=4294967295
2016-12-21 05:20:23.624564 [frame.go:388] I | http2: Framer 0xc4208061c0: wrote WINDOW_UPDATE len=4 (conn) incr=983025
2016-12-21 05:20:23.624627 [frame.go:514] I | http2: Framer 0xc4208061c0: read SETTINGS len=0
2016-12-21 05:20:23.624655 [frame.go:514] I | http2: Framer 0xc4208061c0: read WINDOW_UPDATE len=4 (conn) incr=983025
2016-12-21 05:20:23.624696 [frame.go:388] I | http2: Framer 0xc4208061c0: wrote SETTINGS flags=ACK len=0
2016-12-21 05:20:23.624904 [frame.go:514] I | http2: Framer 0xc4208061c0: read HEADERS flags=END_HEADERS stream=1 len=84
2016-12-21 05:20:23.625020 [frame.go:1463] I | http2: decoded hpack field header field ":method" = "POST"
2016-12-21 05:20:23.625051 [frame.go:1463] I | http2: decoded hpack field header field ":scheme" = "http"
2016-12-21 05:20:23.625118 [frame.go:1463] I | http2: decoded hpack field header field ":path" = "/etcdserverpb.KV/Range"
2016-12-21 05:20:23.625146 [frame.go:1463] I | http2: decoded hpack field header field ":authority" = "172.18.1.1"
2016-12-21 05:20:23.625168 [frame.go:1463] I | http2: decoded hpack field header field "content-type" = "application/grpc"
2016-12-21 05:20:23.625192 [frame.go:1463] I | http2: decoded hpack field header field "user-agent" = "grpc-go/1.2.1"
2016-12-21 05:20:23.625214 [frame.go:1463] I | http2: decoded hpack field header field "te" = "trailers"
2016-12-21 05:20:23.625235 [frame.go:1463] I | http2: decoded hpack field header field "grpc-timeout" = "17998953u"
2016-12-21 05:20:23.625305 [frame.go:514] I | http2: Framer 0xc4208061c0: read DATA flags=END_STREAM stream=1 len=13 data="\x00\x00\x00\x00\b\n\x02/a\x12\x02/b"




2016-12-21 05:20:25.624830 [frame.go:514] I | http2: Framer 0xc4208061c0: read SETTINGS flags=ACK len=0
2016-12-21 05:20:25.626300 [frame.go:388] I | http2: Framer 0xc4208061c0: wrote HEADERS flags=END_HEADERS stream=1 len=14
2016-12-21 05:20:25.626398 [frame.go:388] I | http2: Framer 0xc4208061c0: wrote DATA stream=1 len=52 data="\x00\x00\x00\x00/\n\x1a\b\x8f\xb7\x82\xaa\xbc\xa6\xb4\xa1N\x10\xb3\xbc\x99\x82\xf0Ӎ$xce\xda\x01\x18\xf5\" \x14\x12\x0f\n\x02/a\x10\xba\x1f\x18\xbb\x1f \x02*\x01b \x01"
2016-12-21 05:20:25.626469 [frame.go:388] I | http2: Framer 0xc4208061c0: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=24

you can see that, client read data in last 4s, Is that normal??

I think client should read all data in only 2s because server have send all data at last 2 second.

What did you expect to see?

What did you see instead?

[namusyaka]

I have not investigated this problem deeply, but it might be resolved by specifying TCP_NODELAY.
If the Nagle algorithm is allowed, it aggregates multiple packets at the expense of latency.

If you can provide a minimal project for reproducing the issue, it's helpful for resolving the issue.

[ianlancetaylor]

CC @bradfitz @tombergan