[tinker] Route uvicorn's access log to a plain handler instead of Rich - #2160
Conversation
RichHandler renders every access-log record through a rich Table, about 1.5ms of event-loop CPU per HTTP request. Under rollout load that was 63% of the Tinker API server's CPU: a 4096-sample run spent 12.5s of its 19.9s of server CPU in rich.logging.emit. With a plain StreamHandler for uvicorn.access the same run takes 9.7s and server throughput goes from 337 to 568 samples/s. Startup and error logging keep the Rich handler. Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com> Signed-off-by: Avi Basnet <avigyabb@stanford.edu>
There was a problem hiding this comment.
Code Review
This pull request replaces the default RichHandler with a plain StreamHandler for Uvicorn's access logs to reduce CPU overhead under high request volumes. The reviewer suggested routing access logs to stdout instead of stderr for better log separation in production environments, and using direct class references for configuration consistency.
| "access": { | ||
| "class": "logging.StreamHandler", | ||
| "formatter": "default", | ||
| "stream": "ext://sys.stderr", | ||
| }, |
There was a problem hiding this comment.
There are two improvements we can make to the new access handler configuration:
- Standard Log Separation (
stdoutvsstderr): In production and containerized environments, it is a standard best practice to route HTTP access logs tostdoutand system/error logs tostderr. This allows log aggregators and monitoring tools to easily filter and separate normal traffic logs from errors. Uvicorn's default configuration also routes access logs tosys.stdoutand error logs tosys.stderr. - Configuration Consistency: The
"default"handler configuration uses the class reference directly via"()": RichHandler. Using"()": logging.StreamHandlerfor the"access"handler is more consistent and avoids string-based class resolution.
| "access": { | |
| "class": "logging.StreamHandler", | |
| "formatter": "default", | |
| "stream": "ext://sys.stderr", | |
| }, | |
| "access": { | |
| "()": logging.StreamHandler, | |
| "formatter": "default", | |
| "stream": "ext://sys.stdout", | |
| }, |
Confidence Score: 5/5The PR appears safe to merge with no actionable defects identified. The new handler is compatible with the existing standard formatter, preserves stderr output, and remains isolated by disabled propagation.
|
| Filename | Overview |
|---|---|
| skyrl/utils/log.py | The dedicated access handler preserves the existing formatter, stderr destination, log level, and propagation behavior while removing Rich rendering from request logs. |
Reviews (1): Last reviewed commit: "[tinker] Route uvicorn's access log to a..." | Re-trigger Greptile
…g, keep-alive) (#2163) Stack 4/7. `uvicorn.run`: `backlog=SKYRL_HTTP_CONNECTION_LIMIT` (50k, as on Chuck's branch; the effective value is capped by `net.core.somaxconn`, raise it to match) and `timeout_keep_alive=75`. With 131072 outstanding samples and 212k-token results, each 2048-result completion burst kept the event loop busy ~16 s; uvicorn's 5 s keep-alive then closed every idle client connection, all clients reconnected at once and the 2048-entry accept backlog overflowed, refusing 109k of 131072 requests. With these settings the same run completed 130917 of 131072 with zero forwarding errors and zero reconnects (earlier runs on the 5 s keep-alive showed hundreds to thousands). Neither setting is needed for correctness: the SDK retries refused or dropped connections. They avoid the reconnect storm rather than fix a failure, and with the SDK's per-client in-flight cap the burst that overflowed the backlog does not occur. An earlier revision of this PR also exposed `sample_max_concurrent_requests` from `EngineConfig` via `/client/config`; that was dropped as unnecessary (its default equalled the SDK default, and no measured run depended on it). **Stack** (each PR retargets to `main` as the one below merges) 1. #2160 2. #2161 3. #2162 4. #2163 5. #2164 6. #2165 7. #2166 🤖 Generated with [Claude Code](https://claude.com/claude-code) <!-- CURSOR_SUMMARY --> --- > [!NOTE] > **Low Risk** > Server-only uvicorn listen/keep-alive defaults; no API or auth behavior change, with SDK retries as a fallback. > > **Overview** > The Tinker API server now passes **uvicorn** socket tuning so large completion bursts do not trigger mass client reconnects and accept-queue overflows. > > **`timeout_keep_alive`** is set to **75s** (via `HTTP_KEEP_ALIVE_TIMEOUT_SECONDS`) instead of uvicorn’s **5s** default, so idle SDK connections stay open while the event loop is busy for many seconds during bursts. > > **`backlog`** is set to **`SKYRL_HTTP_CONNECTION_LIMIT`** (default **50k**, overridable by env), so pending connections queue in the kernel instead of being refused when the loop cannot accept fast enough (effective cap is **`net.core.somaxconn`**). > > These are **reliability/performance** knobs, not correctness fixes—the SDK already retries refused or dropped connections. > > <sup>Reviewed by [Cursor Bugbot](https://cursor.com/bugbot) for commit 27c838e. Bugbot is set up for automated code reviews on this repo. Configure [here](https://www.cursor.com/dashboard/bugbot).</sup> <!-- /CURSOR_SUMMARY --> Signed-off-by: Avi Basnet <avigyabb@stanford.edu> Co-authored-by: Claude Fable 5.1 <noreply@anthropic.com>
…2162) Stack 3/7. Fixes the 128x128 `404 Future not found` seen against j316chuck#18. **Chain.** The SDK polls `retrieve_future` with a 45 s client timeout and gives up; the result lands afterwards; the abandoned handler wakes, builds a response nobody receives (uvicorn drops the send to a dead client silently) and starts the short retrieved-TTL clock; the sweeper evicts the result 120 s later; the SDK's retry of the same request_id gets 404, which the SDK treats as fatal. **Fix.** Start the retrieved clock only if `request.is_disconnected()` is false, and raise the retrieved TTL to 300 s so it outlasts the SDK's worst-case re-poll gap (45 s timeout + up to 30 s backoff, twice). `tests/tinker/test_retrieve_future_lost_response.py` reproduces the chain under a real uvicorn socket with shortened TTLs; it fails on `main` and passes here. A second test checks a delivered result still expires on the short clock, so memory stays bounded. Alternative considered: j316chuck#19 drops the retrieved clock and keeps every result for 2048 s. That also fixes the 404 but retains ~35 minutes of results regardless of delivery; with long-output rollouts (hundreds of KB per result) that is tens of GB. Verified at scale: 131072 requests with 5 s engine queueing and 224k SDK-style abandoned polls completed with zero 404s. **Stack** (each PR retargets to `main` as the one below merges) 1. #2160 2. #2161 3. #2162 4. #2163 5. #2164 6. #2165 7. #2166 🤖 Generated with [Claude Code](https://claude.com/claude-code) <!-- CURSOR_SUMMARY --> --- > [!NOTE] > **Medium Risk** > Changes async polling/delivery semantics and HTTP server tuning on the hot `retrieve_future` path; behavior is covered by new integration tests but affects SDK retry reliability under load. > > **Overview** > Fixes fatal **`404 Future not found`** when the SDK abandons a long `retrieve_future` poll (45s client timeout) and retries the same `request_id` after the result is ready. > > **`retrieve_future`** now calls **`mark_retrieved`** (starting the post-delivery eviction clock) only when the client is still connected (`not await req.is_disconnected()`). If the handler finishes building a response after the client disconnected, the short retrieved TTL no longer starts, so the in-memory store keeps the result for a real retry. > > **`ExternalFutureStore`** raises **`_RETRIEVED_TTL_SECONDS`** from 120s to 300s so delivered results still get a grace window that covers worst-case SDK re-poll gaps (timeout + backoff, twice). > > **Uvicorn** startup sets **`timeout_keep_alive=75`** (vs 5s default) and **`backlog=SKYRL_HTTP_CONNECTION_LIMIT`** to reduce idle disconnects and accept-queue overflows during completion bursts. > > Adds **`test_retrieve_future_lost_response.py`** (real socket on Linux) plus test stubs for **`is_disconnected`** on existing API tests. > > <sup>Reviewed by [Cursor Bugbot](https://cursor.com/bugbot) for commit 36188da. Bugbot is set up for automated code reviews on this repo. Configure [here](https://www.cursor.com/dashboard/bugbot).</sup> <!-- /CURSOR_SUMMARY --> --------- Signed-off-by: Avi Basnet <avigyabb@stanford.edu> Co-authored-by: Claude Fable 5.1 <noreply@anthropic.com>
Stack 1/7. Independent of the rest.
RichHandler renders each access-log record through a rich Table, about 1.5 ms of event-loop CPU per HTTP request. Under rollout load that was 63% of the Tinker API server's CPU: profiling a 4096-sample run showed 12.5 s of its 19.9 s of server CPU inside
rich.logging.emit. With a plainStreamHandlerforuvicorn.accessthe same run takes 9.7 s and server throughput goes from 337 to 568 samples/s. Startup and error logging keep the Rich handler.Measured with the load harness in stack 7/7 (
skyrl/benchmarks/load_test_tinker_sampling.py).Stack (each PR retargets to
mainas the one below merges)🤖 Generated with Claude Code
Note
Low Risk
Logging configuration only; no request handling, auth, or data path changes—access output format may look slightly plainer on stderr.
Overview
HTTP access logging for the Tinker API (via
get_uvicorn_log_config) no longer goes throughRichHandler. A dedicatedaccessStreamHandleron stderr uses the same text formatter, whileuvicornanduvicorn.errorstill use Rich for startup, errors, and tracebacks.This targets per-request access log volume: Rich’s table rendering was a major event-loop CPU cost under high QPS. Access lines should read the same format string but without Rich styling.
Reviewed by Cursor Bugbot for commit 254499a. Bugbot is set up for automated code reviews on this repo. Configure here.