add log for request trace #26284
add log for request trace #26284
Conversation
wanx7130
requested review from
WoosukKwon,
robertgshaw2-redhat,
njhill,
ywang96,
comaniac and
alexm-redhat
as code owners
|
👋 Hi! Thank you for contributing to the vLLM project. 💬 Join our developer Slack at https://slack.vllm.ai to discuss your PR in #pr-reviews, coordinate on features in #feat- channels, or join special interest groups in #sig- channels. Just a reminder: PRs would not trigger full CI run by default. Instead, it would only run Once the PR is approved and ready to go, your PR reviewer(s) can run CI to test the changes comprehensively before merging. To run CI, PR reviewers can either: Add 🚀 |
![chatgpt-codex-connector[bot]](https://avatars.githubusercontent.com/in/1144995?s=60&v=4){kind=small}
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
ℹ️ About Codex in GitHub
Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
| def _handle_client_request(self, request_type: EngineCoreRequestType, | ||
| request: Any) -> None: | ||
| """Dispatch request from client.""" | ||
|
|
||
| logger.info("[wxl debug] EngineCore handling client request %s.", request.request_id) | ||
| if request_type == EngineCoreRequestType.ADD: | ||
| self.add_request(request) | ||
| elif request_type == EngineCoreRequestType.ABORT: |
There was a problem hiding this comment.
The new info log dereferences request.request_id before inspecting the request type. When an abort is submitted the request argument is a list[str] of request IDs (see the ABORT branch immediately below), so this line raises AttributeError and prevents _handle_client_request from reaching self.abort_requests. Any client attempting to cancel a request will now crash the engine core loop. Guard the log by checking the request type or by logging the value without assuming a request_id attribute.
Useful? React with 👍 / 👎.
![gemini-code-assist[bot]](https://avatars.githubusercontent.com/in/956858?s=60&v=4){kind=small}
There was a problem hiding this comment.
Code Review
This pull request introduces several logging statements for request tracing. While adding logs is beneficial for debugging, many of the new logs are at the INFO level and contain a [wxl debug] prefix, indicating they are temporary and not suitable for a production environment. These should be removed before merging. Additionally, some existing DEBUG logs have been promoted to INFO level in performance-sensitive areas, which could lead to excessive logging and performance degradation. These should be reverted to DEBUG level.
| logger.info("[wxl debug] %s has already received kvcache and enter into waiting status.", | ||
| request.request_id) |
There was a problem hiding this comment.
This log message appears to be for debugging purposes, as indicated by the [wxl debug] prefix. Such temporary debugging code should be removed before merging into the main branch to avoid cluttering production logs.
| logger.info( | ||
| "[wxl debug] %s is still in WAITING_FOR_REMOTE_KVS state.", | ||
| request.request_id) |
There was a problem hiding this comment.
This log message appears to be for debugging purposes, as indicated by the [wxl debug] prefix, and has been elevated from DEBUG to INFO level. This change could lead to excessive logging in production. It should be reverted to the original DEBUG level and the debug prefix should be removed.
| logger.info( | |
| "[wxl debug] %s is still in WAITING_FOR_REMOTE_KVS state.", | |
| request.request_id) | |
| logger.debug( | |
| "%s is still in WAITING_FOR_REMOTE_KVS state.", | |
| request.request_id) |
| ) -> RequestOutputCollector: | ||
| """Add new request to the AsyncLLM.""" | ||
|
|
||
| logger.info("[wxl debug] Request %s start add_request.", request_id) |
There was a problem hiding this comment.
This log message appears to be for debugging purposes, as indicated by the [wxl debug] prefix. Such temporary debugging code should be removed before merging into the main branch to avoid cluttering production logs.
| """ | ||
|
|
||
| try: | ||
| logger.info("[wxl debug] Request %s start generate.", request_id) |
There was a problem hiding this comment.
This log message appears to be for debugging purposes, as indicated by the [wxl debug] prefix. Such temporary debugging code should be removed before merging into the main branch to avoid cluttering production logs.
| request: Any) -> None: | ||
| """Dispatch request from client.""" | ||
|
|
||
| logger.info("[wxl debug] EngineCore handling client request %s.", request.request_id) |
There was a problem hiding this comment.
This log message appears to be for debugging purposes, as indicated by the [wxl debug] prefix. Such temporary debugging code should be removed before merging into the main branch to avoid cluttering production logs.
| self._update_stats_from_finished(req_state, finish_reason, | ||
| iteration_stats) | ||
|
|
||
| logger.info("[wxl debug] Request %s outputprocessor processed output and will return to client.", req_id) |
There was a problem hiding this comment.
This log message appears to be for debugging purposes, as indicated by the [wxl debug] prefix. Such temporary debugging code should be removed before merging into the main branch to avoid cluttering production logs.
| data_parallel_rank: Optional[int] = None, | ||
| ) -> tuple[Optional[str], EngineCoreRequest]: | ||
|
|
||
| logger.info("[wxl debug] Request %s start process_inputs.", request_id) |
There was a problem hiding this comment.
This log message appears to be for debugging purposes, as indicated by the [wxl debug] prefix. Such temporary debugging code should be removed before merging into the main branch to avoid cluttering production logs.
| logger.info( | ||
| "Transfer KVCache for req %s has completed with handle %s", | ||
| req_id, handle) |
There was a problem hiding this comment.
This informational log is inside a loop that iterates over transfer handles. In a production environment with many transfers, this could lead to excessive logging and performance degradation. Please consider changing this log to the DEBUG level.
| logger.info( | |
| "Transfer KVCache for req %s has completed with handle %s", | |
| req_id, handle) | |
| logger.debug( | |
| "Transfer KVCache for req %s has completed with handle %s", | |
| req_id, handle) |
| logger.info( | ||
| "Transfer KVCache for req %s still in progress with handle %s", | ||
| req_id, handle) |
There was a problem hiding this comment.
This informational log is inside a loop that iterates over transfer handles. In a production environment with many transfers, this could lead to excessive logging and performance degradation. Please consider changing this log to the DEBUG level.
| logger.info( | |
| "Transfer KVCache for req %s still in progress with handle %s", | |
| req_id, handle) | |
| logger.debug( | |
| "Transfer KVCache for req %s still in progress with handle %s", | |
| req_id, handle) |
| for req_id, meta in metadata.requests.items(): | ||
| remote_engine_id = meta.remote_engine_id | ||
| logger.debug( | ||
| logger.info( |
There was a problem hiding this comment.
Changing this log from DEBUG to INFO could result in verbose logging in production, as start_load_kv is called frequently. This might impact performance. It's recommended to revert this to DEBUG level.
| logger.info( | |
| logger.debug( |
Purpose
Test Plan
Test Result
Essential Elements of an Effective PR Description Checklist
supported_models.mdandexamplesfor a new model.