[Serve] incorrect/nondeterministic __CALL__ OK [time] logs with blocking concurrent requests

[paul-twelvelabs]

What happened + What you expected to happen

Deployment logs of the form __CALL__ OK [time] can display the incorrect execution time if the Deployment has synchronous code that blocks the main asyncio event loop. A simple example is the following,

from time import sleep, perf_counter
from ray import serve

@serve.deployment
class BlockingDeployment:
    async def __call__(self):
        # block asyncio event loop
        sleep(1.)


app = BlockingDeployment.bind()
serve.run(app)


# -- benchmark: 5 concurrent requests
import requests
from concurrent.futures import ThreadPoolExecutor

def make_request(_):
    t0 = perf_counter()
    _ = requests.get("http://localhost:8000/")
    print(f">>>> GET {perf_counter() - t0:0.3f} s")


with ThreadPoolExecutor(max_workers=5) as exc:
    print(list(exc.map(make_request, range(5))))

In this toy example, I send 5 concurrent requests to the the BlockingDeployment, which calls time.sleep(1.) and blocks the event loop. I'd expect requests to queue up and take 1, 2, 3, 4, 5s. I see the following output

>>>> GET 1.040 s
(ServeReplica:default:BlockingDeployment pid=34233) INFO...replica.py:378 - __CALL__ OK 1010.3ms
>>>> GET 2.037 s
>>>> GET 3.048 s
>>>> GET 4.050 s
>>>> GET 5.058 s
(ServeReplica:default:BlockingDeployment pid=34233) INFO...replica.py:378 - __CALL__ OK 5027.5ms
(ServeReplica:default:BlockingDeployment pid=34233) INFO...replica.py:378 - __CALL__ OK 5028.3ms
(ServeReplica:default:BlockingDeployment pid=34233) INFO...replica.py:378 - __CALL__ OK 5027.6ms
(ServeReplica:default:BlockingDeployment pid=34233) INFO...replica.py:378 - __CALL__ OK 5028.1ms

The ">>>> GET" logs show the requests are returning in the correct time, but clearly the __CALL__ logs are mostly wrong: the first correctly says ~1s but all successive logs say ~5s. I'd expect something like

(ServeReplica:default:BlockingDeployment pid=34233) INFO...replica.py:378 - __CALL__ OK 1010.3ms
(ServeReplica:default:BlockingDeployment pid=34233) INFO...replica.py:378 - __CALL__ OK 2027.5ms
(ServeReplica:default:BlockingDeployment pid=34233) INFO...replica.py:378 - __CALL__ OK 3028.3ms
(ServeReplica:default:BlockingDeployment pid=34233) INFO...replica.py:378 - __CALL__ OK 4027.6ms
(ServeReplica:default:BlockingDeployment pid=34233) INFO...replica.py:378 - __CALL__ OK 5028.1ms

Moreover, this output is nondeterministic and may change on successive runs,

(ServeReplica:default:BlockingDeployment pid=34233) INFO...replica.py:378 - __CALL__ OK 3014.8ms
(ServeReplica:default:BlockingDeployment pid=34233) INFO...replica.py:378 - __CALL__ OK 3015.0ms
(ServeReplica:default:BlockingDeployment pid=34233) INFO...replica.py:378 - __CALL__ OK 3015.7ms
(ServeReplica:default:BlockingDeployment pid=34233) INFO...replica.py:378 - __CALL__ OK 5023.1ms
(ServeReplica:default:BlockingDeployment pid=34233) INFO...replica.py:378 - __CALL__ OK 5022.4ms

Versions / Dependencies

Python 3.12
ray==2.38.0

Reproduction script

[see above.]

Issue Severity

Low: It annoys or frustrates me.