Measuring gRPC-Java Unary Client Requests Latency From Interceptor

[Yee-Ning Cheng]

I am trying to measure gRPC unary requests from a client.

I have implemented an interceptor very similar to

https://github.com/grpc-ecosystem/java-grpc-prometheus/blob/master/src/main/java/me/dinowernli/grpc/prometheus/MonitoringClientCallListener.java

I also have a metric surrounding the client call and this time is much lower than the time measured from the interceptor.

Is the above interceptor implementation the correct way to measure each unary request from the client?

Thanks

[Carl Mastrangelo]

That is one way.  For more precise (but about as accurate) numbers, consider using a ClientStreamTracer, which you can set on the ManagedChannelBuilder.  That has more fine-grained events about an RPC. 

[Yee-Ning Cheng]

I also have a metric that surrounds the actual blocking call (I am using the blocking stub in this case).

Long time = System.currentTimeMillis();
Userprofile.ReadResponse resp = blockingStub
        .withDeadlineAfter(timeout, TimeUnit.MILLISECONDS)
        .get(req.build());
tick("GrpcClient.Get", System.currentTimeMillis() - time);

The issue is that this metric (the one surrounding the blocking call) is reporting a much lower latency (~100ms vs ~400ms).  Why is there such a discrepancy?  And which one is correct?

I will look into the ClientStreamTracer to see what's there as well. Thanks!

[Carl Mastrangelo]

System.currentTimeMillis() is not ideal for measuring elapsed time.  It's meant for measure the current time.  Instead, try doing:

long startNanos = System.nanoTime();

// ... Do the RPC

long stopNanos = System.nanoTime();

tick("GrpcClient.Get", TimeUnit.NANOSECONDS.toMillis(stopNanos - startNanos));

As for the discrepancy, are you sure you don't have any exceptions being thrown?  If the call failed the time would not be recorded.  This is important for deadline exceeded calls, because they would make the average latency go way up.

[Yee-Ning Cheng]

Ah you were right, user error.. wasn't counting the timings when there was an exception thrown.

Yeah I've been told nanoTime() is better for measuring elapsed time, but actually read somewhere it has a bigger performance hit.

Thanks!

[Carl Mastrangelo]

One of the JVM contributors, Aleksey Shipilёv, has a great blog post on nanoTime.  I highly recommend his short post about it: https://shipilev.net/blog/2014/nanotrusting-nanotime/