gRPC deadline set and call timeout difference lower than deadline time

Question

I am making gRPC calls from a java service, and using withDeadlineAfter(1000, TimeUnit.MILLISECONDS).callApi()

This call times out in most cases (DEADLINE_EXCEEDED). When I checked the logs, it looks as follows

2019-06-14 06:30:09.153 +0000 - [DEBUG] - from io.grpc.internal.ClientCallImpl - Call timeout set to '999861860' ns, due to context deadline. Explicit call timeout was not set.
2019-06-14 06:30:09.909 +0000 - [ERROR] - from application - [ epoch=1560493809909 req=1560493808679.df7ns.10.0.3.96 ] - EVENT_MIGRATION:Failed to create channel: io.grpc.StatusRuntimeException: DEADLINE_EXCEEDED: deadline exceeded after 999695013ns

If I understand correctly, deadline was set at time 06:30:09.153 for the 1 second after 09.153, effectively meaning that the call with the stub should fail after 10.153. The Exception was thrown way before this registered time.

Can someone please explain the behavior?

Answer 1

I'd expect the issue is that the log time was measured from a different point than the deadline time. Namely, the "ns"s were calculated before the logger retrieved the current time.

This would be particularly noticeably with a new Java process because class loading and Java's slow interpreter mean you can see substantial periods of time between code you'd expect to be fast. It'd also be possible if the system was thrashing due to swap or a high load average.