gRPC server has high latencies, but uses almost no CPU

[dominiquelefevre]

Hi,

I've written a trivial gRPC server that receives a request with an array of ints, adds them up, and returns the sum.

A test client does the following:

1. create a randomly-sized array,
2. issue a request to the server,
3. wait for a reply,
4. repeat.

The client and the server communicate over the loopback device, so there should be very little latency in the network link.

I see a curious result in my system: the CPU usage of both the server, and the client, is approx. 10%.

I've implemented the same protocol in go, and the server and the client use 100% CPU, each. The request rate that the go implementation handles is 90x the request rate of the rust implementation. I've also tried "server in rust" + "client in go", and vice versa. In both cases the request rate is as low as with "server and client in rust".

For now, let us disregard the 90x request rate difference. The interesting question is: in the combination "client in go" + "server in rust", why does tonic-based gRPC server limit itself to 10% CPU? Go client can generate many more requests per second than the rust server handles. It feels like a bug in tokio or h2 that does not immediately wake a function blocked in recv().

I've tested with the following packages:

• tonic = "0.1.0-alpha.4",
• hyper = "0.13.0-alpha.4",
• tokio = "=0.2.0-alpha.6",
• rustc 1.39.0-beta.7 (23f8f652b 2019-10-26),
• golang 1.13,
• Linux 5.3.6-300.fc31.x86_64.

Please find the test code attached.
grpc-test-rust.tar.gz
grpc-test-go.tar.gz

What tools do rust and tokio provide to trace the execution of a tokio-based server? How can I see where tonic sleeps, and where does the request handling latency come from?

[LucioFranco]

So a lot of the actual request handling is done by hyper. Tonic is merely just a wrapper around types. That said, there have been many upstream changes to both hyper and tokio that have yet to be fully published. So I am personally waiting for both to get to a state where we should really start looking at optimizing performance until then it doesn't make much sense. Remember tonic is still in an alpha state but we are getting closer.

For perf possibly flamegraph?

[dominiquelefevre]

Hmm. Here is some throughput and latency data for various http frameworks: https://www.techempower.com/benchmarks/#section=data-r18&hw=ph&test=plaintext

It claims that tokio-minihttp has 3.1msec latency for HTTP GETs that return a fixed string "hello world". I see approx. 20msec latency for gRPC requests.

The test of Techempower uses a version of tokio that is not yet async/await-enabled. The 20ms latency, can it be a bug in async/await support in tokio or rust? Who do I talk at tokio/hyper about this?

A flamegraph would be great. How do I generate one for a rust program, or a tokio-based server?

[LucioFranco]

@dominiquelefevre right, tokio 0.1 is a bit different from tokio 0.2. In fact the scheduler has even been completely rewritten! https://tokio.rs/blog/2019-10-scheduler/

You could use this https://github.com/ferrous-systems/flamegraph

[dominiquelefevre]

Fixing #119 actually resolves this one.