Grpc-java: Delay in processing request and sending response under load

[sagarvilas]

I am running a performance test on my unary gRPC server using GHZ, under load about 100K request the response time is high(about 1s to 1.5s) for initial few thousand requests.
After some debugging what I am observing is that there is a delay of about 500ms between the end of server interceptor and invocation of the gRPC service method, and about 500ms delay between the end of service method and invocation of SimpleForwardingServerCallListener.onComplete.

Please let me know if the question is vague or you need more information.

[ericgribkoff]

I would expect that a delayed in the first few thousand response times is due to the JVM warming up. Usually we measure performance after the code path has been invoked 1000s+ times, to ensure the JVM is warmed up: otherwise your measurements are observing latency that includes class loading, JIT compilation, etc.

[sagarvilas]

thanks for the response @ericgribkoff.
I tried running multiple test without restarting the application and observed the same pattern, only difference was that the initial cliff was not that high. From 500ms to it dropped to about 150ms-200ms.
I am more concerned about the delay before and after the service logic. eg.
Total time for processing a single request 375ms
Time between end of gRPC server interceptor(ServerInterceptor.interceptCall) and invocation of gRPC service = 162ms
Time to process the request by gRPC service = 65ms
Time between end of gRPC service and invocation of SimpleForwardingServerCallListener.onComplete = 148ms

[ericgribkoff]

Assuming you are using a Netty server, specify an executor other than the default cached thread pool can boost performance: see e.g. https://stackoverflow.com/questions/42408634/what-is-the-exact-use-of-the-executor-in-grpc-java-s-serverbuilder-does-it-just. For more general tips on optimizing performance, https://grpc.io/blog/optimizing-grpc-part-1/ and part 2 of the same series may be helpful (I don't believe it goes into specific details like picking/tuning the executor, but is a bit more general about making sure operations are non-blocking, etc).

[sagarvilas]

Thanks for the suggestion @ericgribkoff
I am using Netty server and have provided an executor. I have configured 8(2X number of cores) threads for Netty server and 8 threads for gRPC cancellation context executor.
Have checked https://grpc.io/blog/optimizing-grpc-part-1/ , but this does not have the answer I am looking for.
Trying to understand what happens between the gRPC interceptor and service method invocation and end of service and invocation of SimpleForwardingServerCallListener.onComplete.

[ericgribkoff]

@sagarvilas This is probably getting beyond my knowledged of server-side performance optimization, but one thing is still not clear to me from your comments: you mention here that the latency drops from 500ms to 150ms after the JVM warms up. Are you concerned about the 500ms before warmup, or the performance after? The numbers you give in the breakdown seem to be about the time before the JVM warms up, which is generally not what we measure when we talk about performance.

cc @ejona86 if he has any thoughts (I wasn't sure if anyone else still on the team has looked much at optimization)

[sagarvilas]

Sorry for the confusion @ericgribkoff, while the initial latency is a concern, as you said it may be resolved by priming the JVM before the test. I am more concerned about the performance after the JVM has been warmed up. Reposting the example from above, these times are from a test after the JVM has been primed.
Total time for processing a single request 375ms
Time between end of gRPC server interceptor(ServerInterceptor.interceptCall) and invocation of gRPC service = 162ms
Time to process the request by gRPC service = 65ms
Time between end of gRPC service and invocation of SimpleForwardingServerCallListener.onComplete = 148ms
About 80% of the time is outside the business logic.

[ejona86]

How long are you warming up the JVM? I'd suggest warming it up for 30ish seconds, but definitely nothing less than 10 seconds (assuming a small application; larger applications take longer). Java is _very_ slow to start. The very first request for each method has to do classloading, which is very slow. But then the JVM runs in interpreted mode. I generally expect Java to be slower than Python at that point. But as you run longer doing work, Java will compile with increasing levels of optimization.

Total time for processing a single request 375ms

For reference, our benchmarks show a noop RPC taking ~100-200µs round-trip from the client's perspective (not just server processing time).

Time between end of gRPC server interceptor(ServerInterceptor.interceptCall) and invocation of gRPC service = 162ms

The gRPC service isn't called during interceptCall. Instead, it is called at onHalfClose(), which is after the message has been received. So this delay is probably receiving the message or maybe the executor is overloaded.

Time between end of gRPC service and invocation of SimpleForwardingServerCallListener.onComplete = 148ms

And onComplete is called when the response is fully sent. How large are the request and response?

How many concurrent RPCs are being done? How many clients are being used?

[sagarvilas]

thanks for the information @ejona86

I am warming up the JVM for about 30 seconds to 1 minutes.
I am using GHZ with connections= 4, concurrency= 100 and number of requests=100,000.
Request size is about 2 KB(String) and response about 1 KB(String).

As you explained about onHalfClose, I am now overriding onHalfClose in SimpleForwardingServerCallListener to capture the time, this is what I am observing.

Total time taken for processing the request= 382 ms
Time between request reached gRPC server interceptor and invocation on onHalfClose = 177 ms (server interceptors take less than 1 ms)
Time for execution of onHalfClose = time for execution of business logic = 61 ms
Time between end on onHalfClose and invocation of onComplete = 144 ms

So this delay is probably receiving the message or maybe the executor is overloaded.

How to identify if the executor is overloaded.

[ejona86]

I am warming up the JVM for about 30 seconds to 1 minutes.

Excellent, then we can dig more into the numbers.

How to identify if the executor is overloaded.

One way is just to see how many threads Java is using. Sending SIGQUIT to the process can provide a thread dump. But your concurrency level could easily be producing poor results with the default executor, which is just a plain cached thread pool. Setting serverBuilder.executor(...) to a fixed-size thread pool may dramatically reduce memory use under load and number of threads and overall behave better.

But it actually seems your system is saturated and is just overloaded. We'd expect poor latencies in such a case. As you oversaturate a system, the latency increases. Is it safe to assume you are seeing 100% CPU usage?

When doing a QPS benchmark, you should start with a low number of concurrent RPCs (really, concurrent RPCs isn't great, QPS targets would be better as it doesn't have a feedback loop) and increase the number until the QPS stops growing. When the QPS stops growing, you will generally notice the latency starts increasing steadily as there is simply more work than the system can perform (like a long line at the grocery store).

382/61=6.2, so the system seems to be 6.2x oversubscribed. 100/6.2=16 which would be closer to the maximum concurrent RPCs it can handle. Try 10, 15, and 20 concurrent RPCs and see how the latency numbers look.

[sagarvilas]

Thanks a lot @ejona86 and @ericgribkoff

Setting serverBuilder.executor(...) to a fixed-size thread pool may dramatically reduce memory use under load and number of threads and overall behave better.

Yes indeed we are doing it, and we set the size of thread pool to 2X the number of cores, that is the number for which we observe max performance(TPS).

100/6.2=16 which would be closer to the maximum concurrent RPCs it can handle.

Yes that is what we have observed, at low(10 to 20) concurrency the response time was low and consequentially the TPS was high; but we are expecting hundreds of concurrent request. Does this mean gRPC is not the correct framework for such an application

[ejona86]

Yes indeed we are doing it, and we set the size of thread pool to 2X the number of cores, that is the number for which we observe max performance(TPS).

Oh, good. That explains the 177 ms and 144 ms numbers then; that would mainly be the amount of time those callbacks were enqueued on the executor. It seemed like queuing was going on, but I didn't notice above where you did say you were using an 8-thread pool.

Yes that is what we have observed, at low(10 to 20) concurrency the response time was low and consequentially the TPS was high; but we are expecting hundreds of concurrent request. Does this mean gRPC is not the correct framework for such an application

It means your application cannot handle it. It has little to do with gRPC. You need to scale your application to more cores/machines, or make your application more efficient, or reduce incoming load (by failing RPCs or some form of push-back). QPS is again more helpful than concurrent RPCs here as it more easily models user-generated load. If you optimize your service to take 30ms instead of 61ms then generally you would experience half the number of concurrent RPCs but same QPS.

The 144 ms waiting for onComplete shouldn't be observable to the client-side. Instead, there is an additional delay from when the headers are received to when the interceptor is called due to the executor queue. The additional wait between the initial interceptor and onHalfClose would probably be avoided if https://github.com/grpc/grpc-java/issues/7168 was resolved, as it would circumvent going through the executor queue a second time. That would be a quite noticeable reduction in latency, but there'd still be a lot of latency when your system is heavily over-saturated.