RPC timeout set via service config is off by ~1s
- Dominant language
- C++
- Stars
- 45.3k
- Forks
- 11.4k
- Avg merge
- 2d 12h
- Merged PRs (30d)
- 47
Description
### What version of gRPC and what language are you using?
grpcio==1.54.2
### What operating system (Linux, Windows,...) and version?
OSX Ventura 13.6
### What runtime / compiler are you using (e.g. python version or version of gcc)
Python 3.11.4
### What did you do?
tl;dr I find that setting an RPC via service config needs ~1 full second higher than the client/server will actually take. Happens across a variety of timings, and ONLY applies to the service config and NOT to setting a timeout at the actual RPC call.
Started a simple gRPC server that sleeps for a small time. Then perform a client call with a `timeout` in the service config for 1 second more than the configured sleep, which fails unexpectedly and in a shorter time than the timeout.
The below example should sleep for .2s, should timeout in 1.2s, but the client returns a DEADLINE_EXCEEDED in less than .2s.
#### Server
```python
from concurrent import futures
import time
import grpc
import greeting_pb2
import greeting_pb2_grpc
class Greeter(greeting_pb2_grpc.GreeterServicer):
def greet(self, request, context):
print("Got request " + str(request))
time.sleep(0.2)
return greeting_pb2.ServerOutput(message="{0} {1}!".format(request.greeting, request.name))
def server():
server = grpc.server(futures.ThreadPoolExecutor(max_workers=2))
greeting_pb2_grpc.add_GreeterServicer_to_server(Greeter(), server)
server.add_insecure_port("[::]:50051")
print("gRPC starting")
server.start()
server.wait_for_termination()
server()
```
#### Client
```python
import time
import grpc
import greeting_pb2
import greeting_pb2_grpc
options = [("grpc.service_config", '{"methodConfig": [{"timeout": "1.2s", "name": [{}]}] }')]
channel = grpc.insecure_channel(
target="dns:///localhost:50051",
options=options,
)
stub = greeting_pb2_grpc.GreeterStub(channel)
start = time.perf_counter()
try:
response = stub.greet(greeting_pb2.ClientInput(name="Me", greeting="Yo"))
except Exception as e:
response = e
print(response, " in ", time.perf_counter() - start)
```
### What did you expect to see?
I expect this RPC to succeed.
### What did you see instead?
This RPC fails in a shorter time than the timeout. For the example above it fails at 0.14ish seconds rather than 1.2ish seconds.
```
<_InactiveRpcError of RPC that terminated with:
status = StatusCode.DEADLINE_EXCEEDED
details = "Deadline Exceeded"
debug_error_string = "UNKNOWN:Deadline Exceeded {grpc_status:4, created_time:"2023-09-29T11:00:52.966757-05:00"}"
> in 0.14907191699603572
```
This will then succeed if I change the timeout to 1.3 seconds, and this pattern is repeatable for higher values. e.g. a server that sleeps for 3 seconds needs a `serviceConfig` timeout of ~4.1 seconds to succeed.
However, using the timeout in the RPC call instead seems fine. It doesn't seem to have the same off-by-one issue that I find in the service config.
### Anything else we should know about your project / environment?
Contributor guide
Assessment
This issue has not been assessed yet.