Skip to content

[tinker] Route uvicorn's access log to a plain handler instead of Rich - #2160

Merged
avigyabb merged 1 commit into
mainfrom
avi/stack-1-access-log
Sep 5, 2026
Merged

[tinker] Route uvicorn's access log to a plain handler instead of Rich#2160
avigyabb merged 1 commit into
mainfrom
avi/stack-1-access-log

Conversation

@avigyabb

@avigyabb avigyabb commented Sep 5, 2026

Copy link
Copy Markdown
Collaborator

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 plain StreamHandler for uvicorn.access the 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 main as the one below merges)

  1. [tinker] Route uvicorn's access log to a plain handler instead of Rich #2160
  2. [tinker] Forward samples with aiohttp instead of httpx #2161
  3. [tinker] Keep an undelivered sample result alive for the SDK's retry #2162
  4. [tinker] Survive completion bursts at the socket layer (accept backlog, keep-alive) #2163
  5. [tinker] Encode forwarded sample results to proto once and serve them as-is #2164
  6. [tinker] Decode vLLM completion bodies straight into numpy with pysimdjson #2165
  7. [tinker] Load harness for the API server's sampling path at 131k concurrency #2166

🤖 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 through RichHandler. A dedicated access StreamHandler on stderr uses the same text formatter, while uvicorn and uvicorn.error still 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.

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>

@gemini-code-assist gemini-code-assist Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Comment thread skyrl/utils/log.py
Comment on lines +60 to +64
"access": {
"class": "logging.StreamHandler",
"formatter": "default",
"stream": "ext://sys.stderr",
},

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

medium

There are two improvements we can make to the new access handler configuration:

  1. Standard Log Separation (stdout vs stderr): In production and containerized environments, it is a standard best practice to route HTTP access logs to stdout and system/error logs to stderr. 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 to sys.stdout and error logs to sys.stderr.
  2. Configuration Consistency: The "default" handler configuration uses the class reference directly via "()": RichHandler. Using "()": logging.StreamHandler for the "access" handler is more consistent and avoids string-based class resolution.
Suggested change
"access": {
"class": "logging.StreamHandler",
"formatter": "default",
"stream": "ext://sys.stderr",
},
"access": {
"()": logging.StreamHandler,
"formatter": "default",
"stream": "ext://sys.stdout",
},

@greptile-apps

greptile-apps Bot commented Sep 5, 2026

Copy link
Copy Markdown

Confidence Score: 5/5

The 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.

Important Files Changed

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

@avigyabb
avigyabb merged commit 497e73d into main Sep 5, 2026
8 of 9 checks passed
avigyabb added a commit that referenced this pull request Sep 5, 2026
…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>
avigyabb added a commit that referenced this pull request Sep 5, 2026
…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>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant