Connection latency significantly affects throughput

[adg]

I am working on a system that uses GRPC to send 1MB blobs between clients and servers and have observed some poor throughput when connection latency is high (180ms round trip is typical between Australia and the USA).

The same throughput issues are not present when I take GRPC out of the equation. I have prepared a self-contained program that reproduces the problem on a local machine by simulating latency at the net.Listener level. It can run either using GRPC or just plain HTTP/2 POST requests. In each case the payload and latency are the same, but—as you can see from the data below—GRPC becomes several orders of magnitude slower as latency increases.

The program and related files: https://gist.github.com/adg/641d04ef335782648502cb32a03b2b07

The output of a typical run:

$ ./run.sh 
Duration	Latency	Proto

6.977221ms	0s	GRPC
4.833989ms	0s	GRPC
4.714891ms	0s	GRPC
3.884165ms	0s	GRPC
5.254322ms	0s	GRPC

8.507352ms	0s	HTTP/2.0
936.436µs	0s	HTTP/2.0
453.471µs	0s	HTTP/2.0
252.786µs	0s	HTTP/2.0
265.955µs	0s	HTTP/2.0

107.32663ms	1ms	GRPC
102.51629ms	1ms	GRPC
100.235617ms	1ms	GRPC
100.444982ms	1ms	GRPC
100.881221ms	1ms	GRPC

12.423725ms	1ms	HTTP/2.0
3.02918ms	1ms	HTTP/2.0
2.775928ms	1ms	HTTP/2.0
4.161895ms	1ms	HTTP/2.0
2.951534ms	1ms	HTTP/2.0

195.731175ms	2ms	GRPC
190.571784ms	2ms	GRPC
188.810298ms	2ms	GRPC
190.593822ms	2ms	GRPC
190.015888ms	2ms	GRPC

19.18046ms	2ms	HTTP/2.0
4.663983ms	2ms	HTTP/2.0
5.45113ms	2ms	HTTP/2.0
5.56255ms	2ms	HTTP/2.0
5.582744ms	2ms	HTTP/2.0

378.653747ms	4ms	GRPC
362.14625ms	4ms	GRPC
357.95833ms	4ms	GRPC
364.525646ms	4ms	GRPC
364.954077ms	4ms	GRPC

33.666184ms	4ms	HTTP/2.0
8.68926ms	4ms	HTTP/2.0
10.658349ms	4ms	HTTP/2.0
10.741361ms	4ms	HTTP/2.0
10.188444ms	4ms	HTTP/2.0

719.696194ms	8ms	GRPC
699.807568ms	8ms	GRPC
703.794127ms	8ms	GRPC
702.610461ms	8ms	GRPC
710.592955ms	8ms	GRPC

55.66933ms	8ms	HTTP/2.0
18.449093ms	8ms	HTTP/2.0
17.080567ms	8ms	HTTP/2.0
20.597944ms	8ms	HTTP/2.0
17.318133ms	8ms	HTTP/2.0

1.415272339s	16ms	GRPC
1.350923577s	16ms	GRPC
1.355653965s	16ms	GRPC
1.338834603s	16ms	GRPC
1.358419144s	16ms	GRPC

102.133898ms	16ms	HTTP/2.0
39.144638ms	16ms	HTTP/2.0
40.82348ms	16ms	HTTP/2.0
35.133498ms	16ms	HTTP/2.0
39.516466ms	16ms	HTTP/2.0

2.630821843s	32ms	GRPC
2.46741086s	32ms	GRPC
2.507019279s	32ms	GRPC
2.476177935s	32ms	GRPC
2.49266693s	32ms	GRPC

179.271675ms	32ms	HTTP/2.0
72.575954ms	32ms	HTTP/2.0
67.23265ms	32ms	HTTP/2.0
70.651455ms	32ms	HTTP/2.0
67.579124ms	32ms	HTTP/2.0

I theorize that there is something wrong with GRPC's flow control mechanism, but that's just a guess.

[adg]

cc @iamqizhao (and @rsc @robpike @bradfitz who may be interested)

[iamqizhao]

If you observe from 1ms, both grpc and http2 are increasing proportionally. The only issue with grpc is that it is started with much large value (i.e., 107ms vs 12ms). We need to figure out what is the expected value there (this counters my previous observation with http2.0...).

@apolcyn, assign this to you and please help. Thank you.

[adg]

@iamqizhao note the relationship between the simulated latency and the request time.

For HTTP/2, with 0 latency a request takes ~1ms. With 1ms of latency (both up and down) you get requests around 3ms (after the first request, when the connection is established). With 2ms of latency, requests are ~5ms. For 4ms latency, requests take ~9ms. See the pattern? So the actual time spent making HTTP/2 requests, minus the introduced latency, is constant (around 1ms).

Contrast this to the GRPC behavior, where the introduced latency multiplies the overall request time.

We need to figure out what is the expected value there (this counters my previous observation with http2.0...).

Starting with zero latency, the GRPC requests take 4-6ms. What we should see for GRPC requests is a similar pattern, where 1ms of latency yields 8ms requests (6ms + 1ms + 1ms), 2ms latency = 10ms requests, and so on.

[iamqizhao]

as I said, your code cached the string used by http2. For example, 12.423725ms 1ms HTTP/2.0 3.02918ms 1ms HTTP/2.0 2.775928ms 1ms HTTP/2.0 4.161895ms 1ms HTTP/2.0 2.951534ms 1ms HTTP/2.0 the 1st line is much larger than the rest. I believe this means the rest takes advantage of caching. When I said they are both increased proportionally, I meant the first line of the result from http2.

…

On Mon, Jan 9, 2017 at 6:51 PM, Andrew Gerrand ***@***.***> wrote: @iamqizhao <https://github.com/iamqizhao> note the relationship between the simulated latency and the request time. For HTTP/2, with 0 latency a request takes ~1ms. With 1ms of latency (both up and down) you get requests around 3ms (after the first request, when the connection is established). With 2ms of latency, requests are ~4ms. For 4ms latency, requests take ~9ms. See the pattern? So the actual time spent making HTTP/2 requests, minus the introduced latency, is constant (around 1ms). Contrast this to the GRPC behavior, where the introduced latency *multiplies* the overall request time. We need to figure out what is the expected value there (this counters my previous observation with http2.0...). Starting with zero latency, the GRPC requests take 4-6ms. What we *should* see for GRPC requests is a similar pattern, where 1ms of latency yields 8ms requests (6ms + 1ms + 1ms), 2ms latency = 10ms requests, and so on. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#1043 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AJpyLMwAwSMdNAK_VHa1KDXNyjBMIwl0ks5rQvI7gaJpZM4Le51s> .

[adg]

Why would latency have any affect on proto marshaling overhead?

[adg]

12.423725ms	1ms	HTTP/2.0
3.02918ms	1ms	HTTP/2.0
2.775928ms	1ms	HTTP/2.0
4.161895ms	1ms	HTTP/2.0
2.951534ms	1ms	HTTP/2.0

The additional 8-10ms in the first request is certainly setting up the HTTP/TLS connection, which increases proportionally with latency as it involves several round trips.

[iamqizhao]

Err, I see -- I did not look into how you set up the http transport.

[iamqizhao]

yes, it seems this is due to flow control issue -- if I enlarge the flow control window above 1M, this issue goes away.

[presotto]

Perhaps a bit more is happening. At 0s latency grpc is still at most 1/10th the speed of https. Does grpc adjust window to rtt?

[rsc]

I checked in a variant of adg's code that shows the packet breakup and timing.

go get -d -u rsc.io/tmp/grpcbench
cd $GOPATH/src/rsc.io/tmp/grpcbench
bash run.sh

It only shows the output for 32ms round trip time. This is what HTTP/2 POST looks like (the actual output shows packet boundaries within a given millisecond as <-93+89+1024+1024+1024, but I've added all those up for easier reading):

0.036s
	<-184
0.079s
	->1297
0.080s
	<-93
0.117s
	->51
0.118s
	<-12470
0.119s
	<-53573
0.151s
	->56
	<-38
0.184s
	->120
181.526851ms	32ms	HTTP/2.0

0.184s
	<-46
0.217s
	->83
	<-1024
0.218s
	<-64665
0.250s
	->43
65.878218ms	32ms	HTTP/2.0

There is some connection setup in the first one, and then a whole bunch of uninterrupted data transfer. The second one omits the setup but still has the nice fast data transfer.

Compare with GRPC, again two connections:

0.070s
	->9
0.104s
	->13
0.105s
	<-65702
0.138s
	->9
0.171s
	->13
	<-16393
0.206s
	->13
	<-16393
0.243s
	->13
	<-16393
0.281s
	->13
	<-16392
0.316s
	->13
	<-16393
0.351s
	->13
	<-15360
0.352s
	<-1024
0.353s
	<-9
0.384s
	->13
	<-16393
0.417s
	->13
	<-16392
0.450s
	->13
	<-16384
0.451s
	<-9
0.483s
	->13
	<-2048
0.485s
	<-14345
0.516s
	->13
	<-16393
0.549s
	->13
	<-16392
0.582s
	->13
	<-16393
0.615s
	->13
	<-16393
0.648s
	->13
	<-16393
0.681s
	->13
0.714s
	->13
	<-16392
0.747s
	->13
	<-16393
0.780s
	->13
	<-16393
0.813s
	->13
	<-16393
0.846s
	->13
	<-16392
0.879s
	->13
	<-16393
0.912s
	->13
	<-16393
0.945s
	->13
	<-16393
0.980s
	->13
	<-16392
1.014s
	->13
	<-8192
1.015s
	<-8201
1.051s
	->13
1.052s
	<-16393
1.086s
	->13
	<-16393
1.120s
	->13
	<-1024
1.121s
	<-15368
1.154s
	->13
	<-16393
1.187s
	->13
	<-16393
1.220s
	->13
1.221s
	<-16393
1.254s
	->13
1.287s
	->13
	<-16392
1.320s
	->13
1.321s
	<-16393
1.354s
	->13
	<-16393
1.387s
	->13
	<-16393
1.420s
	->13
1.421s
	<-16392
1.458s
	->13
	<-16393
1.490s
	->13
	<-16393
1.527s
	->13
	<-7168
1.528s
	<-9225
1.560s
	->13
	<-13312
1.561s
	<-3080
1.598s
	->13
	<-16393
1.635s
	->13
	<-16393
1.671s
	->13
	<-16393
1.704s
	->13
1.705s
	<-16392
1.737s
	->13
	<-16393
1.770s
	->13
	<-16393
1.803s
	->13
	<-16393
1.838s
	->13
1.870s
	->13
1.871s
	<-16392
1.904s
	->13
	<-16393
1.938s
	->13
	<-13312
1.939s
	<-3081
1.971s
	->13
	<-16393
2.004s
	->13
	<-16392
2.039s
	->13
	<-16393
2.072s
	->13
	<-16393
2.104s
	->13
	<-16393
2.139s
	->13
2.140s
	<-16392
2.173s
	->13
	<-16393
2.205s
	->13
2.206s
	<-16393
2.239s
	->13
	<-16393
2.273s
	->13
2.274s
	<-16392
2.306s
	->13
	<-34
2.338s
	->13
2.371s
	->23
2.404s
	->13
2.437s
	->14
2.470s
	->13
2.504s
	->33
2.501003152s	32ms	GRPC

2.507s
	<-1024
2.508s
	<-64563
2.538s
	->13
2.571s
	->13
	<-16393
2.604s
	->13
	<-15360
2.605s
	<-1033
2.638s
	->13
	<-16393
2.671s
	->13
	<-16392
2.704s
	->13
	<-7168
2.705s
	<-9225
2.738s
	->13
	<-16393
2.771s
	->13
	<-16393
2.804s
	->13
	<-4096
2.805s
	<-12296
2.837s
	->13
	<-16384
2.838s
	<-9
2.871s
	->13
	<-16393
2.904s
	->13
2.905s
	<-16393
2.937s
	->13
	<-16392
2.971s
	->13
	<-16393
3.004s
	->13
3.005s
	<-16393
3.039s
	->13
3.040s
	<-16393
3.072s
	->13
3.106s
	->13
	<-16392
3.139s
	->13
	<-16393
3.171s
	->13
	<-16393
3.204s
	->13
3.205s
	<-16393
3.238s
	->13
	<-16392
3.271s
	->13
	<-16393
3.304s
	->13
3.305s
	<-16393
3.338s
	->13
	<-16393
3.371s
	->13
	<-14336
3.372s
	<-2056
3.405s
	->13
	<-16393
3.438s
	->13
	<-16393
3.471s
	->13
	<-10240
3.472s
	<-6153
3.505s
	->13
	<-16392
3.538s
	->13
	<-16393
3.571s
	->13
	<-1024
3.572s
	<-15369
3.605s
	->13
	<-16393
3.638s
	->13
3.671s
	->13
3.672s
	<-16392
3.705s
	->13
	<-16393
3.738s
	->13
	<-16393
3.771s
	->13
	<-1024
3.772s
	<-15369
3.805s
	->13
	<-16392
3.838s
	->13
	<-16393
3.871s
	->13
3.872s
	<-16393
3.905s
	->13
	<-16393
3.938s
	->13
	<-16392
3.971s
	->13
	<-1024
3.972s
	<-15369
4.004s
	->13
	<-16393
4.041s
	->13
	<-16393
4.078s
	->13
	<-16392
4.113s
	->13
	<-16393
4.146s
	->13
	<-16393
4.179s
	->13
	<-16393
4.212s
	->13
4.245s
	->13
	<-16392
4.278s
	->13
	<-16393
4.311s
	->13
	<-16393
4.344s
	->13
	<-11264
4.345s
	<-5129
4.377s
	->13
	<-16392
4.410s
	->13
	<-16393
4.443s
	->13
	<-5120
4.445s
	<-11273
4.476s
	->13
	<-16393
4.509s
	->13
	<-16392
4.542s
	->13
	<-16393
4.575s
	->13
	<-16393
4.608s
	->13
	<-16393
4.641s
	->13
	<-13312
4.642s
	<-2048
4.643s
	<-1032
4.674s
	->13
	<-34
4.707s
	->13
4.740s
	->11
4.772s
	->13
4.805s
	->14
4.838s
	->13
4.872s
	->11
2.367555959s	32ms	GRPC

It looks like there are two problems. The first one is that GRPC appears to have added its own flow control on top of HTTP/2's flow control (on top of TCP's flow control), and it has a fixed 16 kB window. The second is that it looks like HTTP/2 POST is compressing while GRPC is not: in addition to having better (no added) flow control, the posts transfer only about 64 kB of data in total. Either that or the test is broken.

[iamqizhao]

@rsc Thanks for investigation. Nice findings. In gRPC-Go, there is no HTTP/2 flow control (FYI, Brad and I have not finished the migration to the standard HTTP2 package yet and gRPC-Go still uses its own native HTTP2 implementation). And yes gRPC does not apply compression by default.

The root case that the latency of gRPC-Go is not equal to network RTT + constant processing time is because of its flow control mechanism. Currently, it takes a simplistic form -- it has a fixed 16KB window update as Russ discovered. It does not tune according to network RTT and incoming message sizes so that it favors low latency networks and sucks in long-haul networks (as shown in this issue). The current mechanism is the initial version and was consistent across languages. Recently, gRPC-C added some more intelligence to its flow control and more is under design. I summarize the effort we will put in this area as follows:
i) window size tuning upon message size. This should fix this issue;
ii) window size tuning according to network RTT (under design);
iii) public surface to allow user to tune flow control parameters and enforce a server-scoped flow control limit (under design).

[rsc]

Can user client code change the fixed flow control window size?

Can user client code enable compression?

[iamqizhao]

Can user client code change the fixed flow control window size?

Currently they cannot. This is the 3rd effort I mentioned in the previous reply.

Can user client code enable compression?

Yes, with grpc.WithCompressor dial option.