Q: DEADLINE EXCEEDED after with time value lower than the grpc call deadline value

[lmcdasi]

I would like to understand why a DEADLINE EXCEEDED would report that it ended earlier than the actual value.

For example, the grpc unary request has a deadline of 15s. But the deadline exceeded occurs after a lower value. For example:

2024-04-15T23:41:49.407Z <> {thread=thread-0} ERROR: CallEventType CALL_ENDED failed with status Status{code=DEADLINE_EXCEEDED, description=deadline exceeded after 11.539017198s. [closed=[], open=[[remote_addr=host/hostIp:443]]], cause=null}
io.grpc.StatusRuntimeException: DEADLINE_EXCEEDED: deadline exceeded after 11.539017198s. [closed=[], open=[[remote_addr=host/hostIp.168:443]]]

2024-04-15T23:41:49.434Z <> {thread=thread-0} ERROR: CallEventType CALL_ENDED failed with status Status{code=DEADLINE_EXCEEDED, description=deadline exceeded after 6.302487311s. [closed=[], open=[[remote_addr=host/hostIp:443]]], cause=null}
io.grpc.StatusRuntimeException: DEADLINE_EXCEEDED: deadline exceeded after 6.302487311s. [closed=[], open=[[remote_addr=host/hostIp:443]]]

And sometimes I do have a value close to what was requested:
2024-04-15T23:48:53.967Z <> {thread=thread-0} ERROR: CallEventType CALL_ENDED failed with status Status{code=DEADLINE_EXCEEDED, description=deadline exceeded after 13.288090524s. [closed=[], open=[[remote_addr=host/hostIp:443]]], cause=null}
io.grpc.StatusRuntimeException: DEADLINE_EXCEEDED: deadline exceeded after 13.288090524s. [closed=[], open=[[remote_addr=host/hostIp:443]]]

2024-04-15T23:45:25.920Z <> {thread=thread-0} ERROR: CallEventType CALL_ENDED failed with status Status{code=DEADLINE_EXCEEDED, description=deadline exceeded after 14.999876625s. [closed=[UNAVAILABLE, UNAVAILABLE], open=[]], cause=null}
io.grpc.StatusRuntimeException: DEADLINE_EXCEEDED: deadline exceeded after 14.999876625s. [closed=[UNAVAILABLE, UNAVAILABLE], open=[]]

I do have keepalives enabled. The rate is every 30s & a timeout of 15s. I did not capture any issue related to them.

[panchenko]

Deadline is passed as an absolute value of timestamp, so I would suggest checking time is synchronised on these computers.

[ejona86]

"deadline exceeded after" is generated by the client. So network-delays aren't typically involved.

[ejona86]

What version of gRPC are you using? There was a delay for the first RPCs on a channel that wasn't included in that deadline message, and newer versions of gRPC report back the extra delay those RPCs experienced.

My best guesses on how this is happening:

1. The machine is heavily saturated. If it is seeing long periods of 100% CPU usage, this could be believable
2. You have the architecture A→B→C, and a B→C RPC uses a smaller timeout than A→B's 15 seconds. Then, when the B→C deadline is exceeded, B blindly copied the status back to A.

I don't think A→B→C would likely produce these errors without B shortening the deadline (unless the CPU is fully saturated). In that case, there's one timer on B that cancels A→B with RST_STREAM and B→C with a pretty Status. So you'd need a race on B for the Status to beat the fast RST_STREAM. And you'd need that to arrive at A before it has processed its own timer (which starts 1 RTT earlier). We know the race on A can happen, but it should be rare (definitely seen in practice, but not frequent).

[lmcdasi]

I believe I'm using version 1.51.0 and planning to update to a newer version. I'm even seeing negative values:

CallEventType CALL_ENDED failed with status Status{code=DEADLINE_EXCEEDED, description=ClientCall started after deadline exceeded: -18.425580045s from now, cause=null}

OK for CPU usage impact. I'm planning to monitor it.

In my setup, the client is onPrem talking to a server on Azure VM. So the "middle man" would be envoy if no proxy is in between. The remote service just stores an info in a Redis DB and responds but I can read it's code and see if it does something to shorten the deadline.

When I read this: open=[[remote_addr=host/hostIp:443]], the open would be the proxy/envoy - not the actual service.

Can I "assume" that when I see the "open" then the service on cloud was "busy" and could not process my request in the 15s deadline that was set in the unary call ?

[ejona86]

1.59 had the improved logging for the very first RPCs: "core: enhance error message in the case of DEADLINE_EXCEEDED to indicate name resolution delay."

Envoy doesn't generate a message like that, so that means only the client is involved.

Can I "assume" that when I see the "open" then the service on cloud was "busy" and could not process my request in the 15s deadline that was set in the unary call ?

Yes, "open" means "there's an active RPC to that server." Although there can be sources of buffering, so the server didn't get the "full" time. When that happens, we include details (mostly buffered_nanos) that indicate how long it was buffered in that status message (of which there were none). Also, if the RPC was retried, the second request has less time to process (the time of the first request and any delay between attempts is lost).

[lmcdasi]

OK _ I will plan an upgrade. Thank you for your feedback.