Can ClientCall.Listener.onClose() ever run after asyncUnaryCall completes.

[catchpolecanva]

We use a ClientInterceptor with a SimpleForwardingClientCallListener to track call latency and other various metrics for gRPC calls. Under some circumstances, we notice that our latencies blow out from a typical 50 ms, up to 2000 ms. I accept that there are all sorts of reasons for delayed requests on a large busy system, especially with load balancers involved. The time of our actual server method call does not change, nor are there backed up requests etc, so we think it's related to the communications layer, not the call itself.

I put an extra timer around whole call, from the caller's perspective. I'm seeing initial metrics which suggest that the time observed by the caller of the method is in the expected range but sometimes the time recorded by ClientCall.Listener.onClose() is much higher.

If I put a sleep in onClose I can see it delays the whole call, so this suggests it's not running async, or at least not by default.

My question is simply, are their circumstances where gRPC internally will allow the asyncUnaryCall to complete before it has run ClientCall.Listener.onClose() from a ClientInterceptor?

My metrics suggest this can happen, but there is also the possibility my metrics are inaccurate.

[AgraVator]

No, the ListenableFuture returned by an asyncUnaryCall will not complete before the ClientCall.Listener.onClose() method is invoked.

The completion of the future is fundamentally tied to the gRPC call's lifecycle, which terminates with the onClose event. Your experiment with sleep in onClose correctly demonstrates this: onClose is on the critical path for the call's completion. The future's result (or exception) is set only after the listener has been notified of the call's closure.

Your metrics are not necessarily inaccurate, but they are likely revealing a delay in a different place than you suspect.

What's Likely Happening?
The discrepancy you're observing—where the caller gets the result quickly but the onClose timer records a much longer duration—points to a delay occurring between the time the gRPC transport layer receives the final response from the server and the time your onClose code actually executes.

There are two primary culprits for this kind of delay:

Executor Saturation: The ClientCall.Listener methods, including onClose, are run on an executor thread pool associated with the gRPC channel. If this executor is busy with other tasks or is under-provisioned (has too few threads), the task of invoking onClose can sit in a queue for a significant amount of time. The network call is finished, but the application code to handle its completion is waiting for a thread. This is a very common cause of this exact issue.

Other Interceptors in the Chain: Your SimpleForwardingClientCallListener delegates to the next listener in the chain. If another interceptor's onClose method, which runs after yours, performs a slow or blocking operation, it will delay the final completion of the call and the ListenableFuture. Your timer inside onClose stops, but the call itself remains "in-flight" until the entire chain is unwound.

Review the Entire Interceptor Chain: Carefully inspect the order and implementation of all client interceptors. Look for any potentially blocking I/O or long-running computations within any onClose method.

Profile Your Application: Use a profiler (like YourKit, JProfiler, or VisualVM) to trace the execution when these latency spikes occur. You should be able to see threads from the gRPC executor pool and identify what they are waiting for. This will definitively show if they are blocked or if your onClose task is simply waiting in a long queue.

[catchpolecanva]

Hello Abhishek,

Thank you for your detailed response. I was fairly certain this was the case, but wanted to confirm as I was running out of options for my investigation.

What I was actually observing was "internal" times tracked by an interceptor larger than a timer I placed around the call externally, which didn't make any sense unless the call was completing late.

But, at this stage I'm fairly sure that my external metric is error in a way that it interacts with a secondary future which was excluding certain data points from a shorter timeout than the gRPC call's deadline. I guess this is a better result than gRPC behaving in an unexpected way :)

[AgraVator]

Of course, glad I could help! Closing this for now.
Do let us know if you find anything else.