perf: build log messages lazily so filtered-out log records cost nothing (rebase of #35703) - #35727
Conversation
|
osv-scan is red here for a reason unrelated to this diff: new advisories against cryptography 48.0.1 (GHSA-jwv3-5hgf-82ww, GHSA-m2h6-j472-rp4c, GHSA-g6cj-pr64-35w5) published after the last green staging run at 491eda3. The fixed versions are 49.0.0 and 50.0.0, but pyproject.toml pins cryptography>=48.0.1,<49.0, so this needs a pin bump plus relock in its own PR and will fail on every open PR until that lands. Out of scope here, not fixing it in this PR Generated by Claude Code |
litellm's loggers sit at INFO by default; the proxy sets that level explicitly and the SDK inherits root's WARNING, so every debug record is discarded. The message gets built anyway. 2877 logging calls interpolate their payload into an f-string before the call runs, so the work happens on every request and the result is thrown away. The expensive sites stringify a whole message list or kwargs dict, so the cost grows with conversation length
Passing the values as %-style arguments hands them to record.getMessage(), which only runs once a record has passed the level check. With the level turned up the emitted lines are byte-identical, including f"{x=}" sites, which map to %r. A 60-message chat completion runs 22% faster through litellm.completion and allocates 163 kB less; a 20-message one runs 11% faster
f-strings carrying a format spec are left as they are, since %-style has no faithful equivalent for something like {ratio:.1%}, and those sites interpolate scalars rather than payloads. The added test walks the package and fails on any new eager logging call
1b60d61 to
b248f7b
Compare
Codecov Report❌ Patch coverage is 📢 Thoughts on this report? Let us know! |
|
On the codecov/patch failure: 877 of the changed lines are debug and info log call sites spread across 400 files, and unit tests do not execute most of those paths, so patch coverage on this diff cannot approach the 68% target. That is inherent to a mechanical logging rewrite rather than a coverage gap introduced by it; the change is guarded globally by the AST test in tests/test_litellm/test_logging.py, which fails if any call site regresses to eager interpolation. The original #35703 had the same codecov result, so this check needs a manual waive when merging Generated by Claude Code |
|
|
4 participants
TLDR
Problem this solves:
How it solves it:
Relevant issues
Carries #35703, which fixes #35699
Linear ticket
Pre-Submission checklist
@greptileaito re-request a review after pushing changes)Delays in PR merge?
If you're seeing a delay in your PR being merged, ping the LiteLLM Team on Slack (#pr-review).
Screenshots / Proof of Fix
The first commit is the single commit from #35703, rebased onto litellm_internal_staging at c6a796a with authorship preserved. The full measurements and the byte-identical output equivalence proof over all 2877 rewritten call sites are in the original PR body and were captured at 1f7eafd; the rebase changes nothing about those call sites, so they carry over
What the rebase itself changed, beyond replaying the commit:
litellm/integrations/rubrik.pywas rewritten on staging by #35722 after the original PR was cut, which produced three conflicts. All three resolve to the newer staging code, with the one f-string logging call inside the conflicted region ("%s hook failed") converted to %-style args. The rubrik rewrite also introduced 10 new eager logging calls outside the conflicted regions; the enforcement test added by the original PR fails on them, so they are converted in the same mechanical way as the other 2877 siteslitellm/proxy/litellm_pre_call_utils.pyconflicted with #35678, which routes the request headers debug log throughredact_credential_headers. The resolution keeps the redaction and passes the redacted mapping as a %-style arg, so the security behavior of #35678 is unchangedThe second commit fixes the CI failures the first run surfaced: 9 tests added on staging after the original PR was cut assert on the log message via a mocked logger's
call_args[0][0], which now sees the%stemplate instead of the rendered string. Each is updated to renderargs[0] % args[1:](or assert the exact lazy call), which keeps the assertions meaningful and additionally makes them cover the lazily passed values. All 51 affected test cases pass locally:.venv/bin/python -m pytest tests/test_litellm/integrations/newrelic/test_newrelic.py::TestParseBoolEnv tests/test_litellm/proxy/auth/test_model_checks_fallbacks.py ...reports41 passed, and the second batch covering the anthropic cache control, MCP server, MCP REST and team endpoint tests reports10 passedVerified at 0ff2152 that the enforcement test's AST scan over the whole
litellmpackage reports 0 eager logging calls and thatruff format --checkandruff check(0.15.3) pass on both resolved production filesNote on remaining red checks: osv-scan fails repo-wide on new cryptography 48.0.1 advisories whose fix versions are blocked by the
<49.0pin in pyproject.toml (needs its own PR), and codecov/patch is structurally low because most changed lines are debug log call sites that unit tests never execute; the AST enforcement test is the real guardType
🚄 Infrastructure
Changes
Identical to #35703: every logging call on
verbose_logger,verbose_proxy_logger,verbose_router_loggerand the module-level stdlib loggers passes values as %-style arguments instead of interpolating an f-string before the level check, plustests/test_litellm/test_logging.pygains the AST test that fails on any new eager call site. On top of that, the 10 rubrik call sites, 2 conflict resolutions and 9 test assertion updates described aboveIf preferred, a maintainer with access to the fork can instead force-push this branch to
Classic298:perf_lazy_debug_loggingto update #35703 in place and keep its approval:Final Attestation