Status CANCELLED under load

[grigorryev]

What version of gRPC are you using?

1.14.0

Hi,

I have a service that communicates with upstream via reactive-grpc. It performs both unary calls and subscriptions.

Under high load, after request/subscriptions rate exceeds some threshold, the service starts receiving StatusRuntimeExceptions with status CANCELLED.

I performed some Wireshark investigations and discovered that the amount of time taken by the service to respond to http2 PING sent by the upstream gradually increases with the load. At the moment it exceeds keepalive timeout configured for the upstream, the upstream cancels the call.

Are there any ways to configure/examine the process of http2 ping-pong under grpc? What aspects of configuration may affect this process? What code is responsible for this processing? Where should I put a breakpoint? Any explanations, suggestions, and considerations are welcome.

I'm not sure what particular information about my configuration I should provide, but I will provide anything required.

Thank you!

[dapengzhang0]

I'm not clear about what you want to configure. If you would like to make keepalive timeout larger, you can use ManagedChannelBuilder.html#keepAliveTimeout

[ejona86]

What implementation of gRPC is the server? Is there a proxy involved?

[ejona86]

Approximately how fast is the network bandwidth to upstream? Or rather, how much bandwidth is the connection using when under load? We just need rough numbers, like 1, 10, 100 Mbps.

[grigorryev]

The server uses Rust implementation of gRPC, which, as far as I know, is a thin wrapper over C++ implementation. It's 1 Gbps network between 2 microservices, no proxies.
Server keepalive timeout is set to 3s, and, of course, can be increased, but it doesn't look like a proper solution.

[grigorryev]

Wireshark screenshots:

1. Service starts the request with HEADERS:

and then DATA (it's empty because the request is empty by business logic):

2. Upstream replies with HEADERS with status 200, flags.end_stream=True and grpc-message='Cancelled'.

and immediately RST_STREAM

[ejona86]

I assume you're using the "grpcio" crate, which does look to be using C core (vs "grpc-rust").

The response HEADERS indicate the server is choosing to cancel. It's unclear why it is doing that, but it may be based on server-side logic. The client doesn't have direct control over any of that. But it is clear this is not related to keepalive; keepalive kills the connection when it fails.

Both HEADERS (request and response) are for stream 2573, whereas the DATA was for stream 2577. You need to follow each stream independently to see what was happening.

The RST_STREAM(NO_ERROR) at the end was for stream 2573. That is "normal" for a server to send immediately following a HEADERS (see the last paragraph of section 8.1) but only really needed when the client has not yet half-closed (look for "End Stream: True" in Flags in wireshark; the DATA frame you showed did half-close). That makes me think that the client didn't send any DATA frame for stream 2573.

@grigorryev, can you confirm that when this happens, there is no DATA frame (rather, no End Stream: True) from the client to the server? Also, how much time passed between the client's HEADERS and the server's HEADERS?

[grigorryev]

My bad, I accidentally got an image of DATA from another thread, but they are equivalent:

and it has End Stream: True in it.
It's 200ms between client's HEADERS and server's HEADERS.

What worries me about keepalive, is that this cancellation happens just after service start to respond to upstream's PING for too long.
Look at this:

I filtered the dump for stream 2573 and ping/pong messages. It normally takes less than a second to respond to PING from upstream but at some point, it starts taking more than 3sec (which is the upstream's keepalive timeout) for some reason. And the upstream immediately responds with 'Cancelled' after that.

Another thing pointing that problem is with the client, is that these cancellations correlate with client's performance. When running on production hardware it requires significant load (~1000rps) to start receiving cancellations, but on my Macbook, when the service is launched together with load framework and under debug, cancellations start to happen at few requests per second. (In both experiments the same upstream was used.)

[ejona86]

I'm sorry I've not replied. A lot has been going on for me.

I really don't think this is related to keepalive. Keepalive pings don't happen this frequently. These pings are likely bandwidth-delay product (BDP)-monitoring pings, for adjusting window sizes. I don't think they are directly related to the cancellation.

The 3 sec difference looks like it could be okay, since that is a 3 second difference between the client's PING(ACK) (aka "pong") and the server's next ping. That's normal. These BDP pings should only be used when the server is writing out DATA already. Only the PING(ACK) might be by itself. I'm not saying that the 3 second pause on the server-side is normal; just that the PINGs look fine.

I think this "Cancelled" stuff is the server shedding load or something similar. I grepped C core, and see "Cancelled" within src/core/lib/iomgr/error.cc. I don't see any such string in Rust (even ignoring the quotes). So I think this error is being generated by C core.

I started to file an issue at https://github.com/grpc/grpc/, but I expect they'll want you to try https://github.com/grpc/grpc/blob/master/TROUBLESHOOTING.md to see if the logs provide information about what went wrong. That's worth a try. If it turns out to be too hard, you/we can file an issue even without that information. All we really know at this point is "under load C core generates a status message 'Cancelled'" (note that it is important it is a status message; that's fairly unique/rare for cancellation).

[creamsoup]

closing due to inactivity. feel free to reopen it.