vllm-project / vllm-project/aibrix
[Bug] Benchmark connection timeout when creating or receiving chunks
- Dominant language
- Go
- Stars
- 5.1k
- Forks
- 694
- Avg merge
- 1d 19h
- Merged PRs (30d)
- 98
Description
### 🐛 Describe the bug
When evaluating workload with benchmark tool under high concurrency, we observed inconsistent exception handling behavior for timeout errors in the `send_request_streaming` function. The two-level nested try/except structure leads to different capture paths and result statuses for timeouts occurring at different stages:
1. `client.chat.completions.create` executes successfully but `async for chunk in response_stream` timeout when receiving chunks. I checked it by counting received chunks and got:
```
ERROR:root:Request 81: Stream interrupted: ReadTimeout: , expect chunk: 771, but interrupt after 733 chunks
ERROR:root:last_chunk premier, last_chunk_time 988153.846543041, distance from now 60.00374454190023
INFO:root:Request 81: Completed successfully. Tokens: 0, Latency: 87.17s
```
where 60s is default timeout set in `config.yaml`. And in this case, the request will be tagged "successful", though "usage chunk" is not received and input/output tokens will be set 0.
2. `client.chat.completions.create` fails. The request will be tagged "error" in this case, and its log will be like:
```
ERROR:root:Request 623: Error (APIConnectionError): Connection error.
```
and `output.jsonl` will record detailed error:
```
{"request_id": 73, "status": "error", "error_type": "APITimeoutError", "error_message": "Request timed out.", "error_traceback": "Traceback (most recent call last):\n File \"/Users/bytedance/sdk/anaconda3/envs/aibrix/lib/python3.10/site-packages/httpx/_transports/default.py\", line 101, in map_httpcore_exceptions\n yield\n File \"/Users/bytedance/sdk/anaconda3/envs/aibrix/lib/python3.10/site-packages/httpx/_transports/default.py\", line 394, in handle_async_request\n resp = await self._pool.handle_async_request(req)\n File \"/Users/bytedance/sdk/anaconda3/envs/aibrix/lib/python3.10/site-packages/httpcore/_async/connection_pool.py\", line 256, in handle_async_request\n raise exc from None\n File \"/Users/bytedance/sdk/anaconda3/envs/aibrix/lib/python3.10/site-packages/httpcore/_async/connection_pool.py\", line 236, in handle_async_request\n response = await connection.handle_async_request(\n File \"/Users/bytedance/sdk/anaconda3/envs/aibrix/lib/python3.10/site-packages/httpcore/_async/connection.py\", line 103, in handle_async_request\n return await self._connection.handle_async_request(request)\n File \"/Users/bytedance/sdk/anaconda3/envs/aibrix/lib/python3.10/site-packages/httpcore/_async/http11.py\", line 136, in handle_async_request\n raise exc\n File \"/Users/bytedance/sdk/anaconda3/envs/aibrix/lib/python3.10/site-packages/httpcore/_async/http11.py\", line 106, in handle_async_request\n ) = await self._receive_response_headers(**kwargs)\n File \"/Users/bytedance/sdk/anaconda3/envs/aibrix/lib/python3.10/site-packages/httpcore/_async/http11.py\", line 177, in _receive_response_headers\n event = await self._receive_event(timeout=timeout)\n File \"/Users/bytedance/sdk/anaconda3/envs/aibrix/lib/python3.10/site-packages/httpcore/_async/http11.py\", line 217, in _receive_event\n data = await self._network_stream.read(\n File \"/Users/bytedance/sdk/anaconda3/envs/aibrix/lib/python3.10/site-packages/httpcore/_backends/anyio.py\", line 32, in read\n with map_exceptions(exc_map):\n File \"/Users/bytedance/sdk/anaconda3/envs/aibrix/lib/python3.10/contextlib.py\", line 153, in __exit__\n self.gen.throw(typ, value, traceback)\n File \"/Users/bytedance/sdk/anaconda3/envs/aibrix/lib/python3.10/site-packages/httpcore/_exceptions.py\", line 14, in map_exceptions\n raise to_exc(exc) from exc\nhttpcore.ReadTimeout\n\nThe above exception was the direct cause of the following exception:\n\nTraceback (most recent call last):\n File \"/Users/bytedance/sdk/anaconda3/envs/aibrix/lib/python3.10/site-packages/openai/_base_client.py\", line 1519, in request\n response = await self._client.send(\n File \"/Users/bytedance/sdk/anaconda3/envs/aibrix/lib/python3.10/site-packages/httpx/_client.py\", line 1629, in send\n response = await self._send_handling_auth(\n File \"/Users/bytedance/sdk/anaconda3/envs/aibrix/lib/python3.10/site-packages/httpx/_client.py\", line 1657, in _send_handling_auth\n response = await self._send_handling_redirects(\n File \"/Users/bytedance/sdk/anaconda3/envs/aibrix/lib/python3.10/site-packages/httpx/_client.py\", line 1694, in _send_handling_redirects\n response = await self._send_single_request(request)\n File \"/Users/bytedance/sdk/anaconda3/envs/aibrix/lib/python3.10/site-packages/httpx/_client.py\", line 1730, in _send_single_request\n response = await transport.handle_async_request(request)\n File \"/Users/bytedance/sdk/anaconda3/envs/aibrix/lib/python3.10/site-packages/httpx/_transports/default.py\", line 393, in handle_async_request\n with map_httpcore_exceptions():\n File \"/Users/bytedance/sdk/anaconda3/envs/aibrix/lib/python3.10/contextlib.py\", line 153, in __exit__\n self.gen.throw(typ, value, traceback)\n File \"/Users/bytedance/sdk/anaconda3/envs/aibrix/lib/python3.10/site-packages/httpx/_transports/default.py\", line 118, in map_httpcore_exceptions\n raise mapped_exc(message) from exc\nhttpx.ReadTimeout\n\nThe above exception was the direct cause of the following exception:\n\nTraceback (most recent call last):\n File \"/Users/bytedance/bytedance/aibrix-main/benchmarks/client/client.py\", line 68, in send_request_streaming\n response_stream = await client.chat.completions.create(\n File \"/Users/bytedance/sdk/anaconda3/envs/aibrix/lib/python3.10/site-packages/openai/resources/chat/completions/completions.py\", line 2028, in create\n return await self._post(\n File \"/Users/bytedance/sdk/anaconda3/envs/aibrix/lib/python3.10/site-packages/openai/_base_client.py\", line 1784, in post\n return await self.request(cast_to, opts, stream=stream, stream_cls=stream_cls)\n File \"/Users/bytedance/sdk/anaconda3/envs/aibrix/lib/python3.10/site-packages/openai/_base_client.py\", line 1537, in request\n raise APITimeoutError(request=request) from err\nopenai.APITimeoutError: Request timed out.\n", "input": [(omitted)], "output": "", "prompt_tokens": 14336, "output_tokens": 0, "total_tokens": 14336, "latency": 61.070314833079465, "throughput": 0, "start_time": 991265.530446125, "end_time": 991326.600760958, "ttft": null, "tpot": null, "target_pod": "", "target_request_id": "", "session_id": null}
```
The above 2 error occurs more frequently with larger QPS (reaching 5% when QPS=3, which is intuitively acceptable for 6 vLLM instances on 6 GPU).
It seems not working to set timeout larger. I tried to set `timeout=3600s`, even the whole test time is also 3600s.
Another strange info is in gateway logs:
```
I0808 08:22:03.332349 1 gateway_rsp_body.go:237] "request_end" request_id="a57b7902-f194-486b-b4c4-50186de43b77" model_name="qwen" prompt_tokens=3297 completion_tokens=382 total_tokens=3679 target_pod="qwen-555f5fddfd-q65tv" outstanding_request_count=0 routing_time_taken="3m16.67010448s" total_time_taken="3m24.732934225s"
// prompt_tokens=3297
// completion_tokens=382
// routing_time_taken="3m16.67010448s"
// total_time_taken="3m24.732934225s"
```
It rarely shows an extremely large routing time, which normally to be about several ms. Which may be relative with these errors.
**workload**
requests: 11000
time: 1h
input/output avg length: 7000/170
deployment: 6 vLLM on 6 GPU
### Steps to Reproduce
1. Deploy AIBrix on VKE as introduced
2. Using benchmark with provided mooncake workload and set scale large
### Expected behavior
No timeout error met for all requests.
### Environment
AIBrix version: released v0.7.0, 6 vLLM instance
Environment: VKE
Model: Qwen/Qwen2.5-7B-Instruct
Contributor guide
Assessment
This issue has not been assessed yet.