Repository navigation
perf: format local evaluation debug logs lazily - #81
Conversation
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
|
This is a real pain point for us at WeWard, with a significant performance impact. We patched it locally and saw immediate benefits. |
sandeep-madugula
left a comment
There was a problem hiding this comment.
Reviewed with Codex. No blocking code findings: deferred logging formatting removes the expensive flag-config representation from the disabled-DEBUG evaluation path, and both enabled and disabled DEBUG behavior are covered by the added tests. The disabled-DEBUG regression test also fails against the original implementation as expected.
Updated the branch from main and fixed an existing CI runner incompatibility by pinning the unit-test runner to Ubuntu 22.04; Ubuntu 26.04 does not provide Python 3.8.
Full validation passed on Python 3.8, 3.12, and 3.14: each job ran 210 tests, with 4 existing skips. Run: https://github.com/amplitude/experiment-python-server/actions/runs/42886326835
That run used temporary maintainer branch ci/validate-python-pr-81-20261110 (73ee6b9), based on PR head dfdd86b. The source and tests are identical to the PR; the only additional difference enables the workflow on the temporary branch. The fork PR workflow has empty API_KEY/SECRET_KEY/EU_API_KEY/EU_SECRET_KEY values and consequently fails the seven cohort integration tests; those same tests pass in the maintainer run with the existing Unit Test environment secrets.
Summary
LocalEvaluationClient.evaluate_v2logs the whole flag config snapshot at DEBUG on every call:The f-string is built before the logger checks its level, so every evaluation renders every flag config to text, even when only one flag is requested and even when DEBUG is disabled. DEBUG is disabled by default:
LocalEvaluationConfigsets the default logger toWARNINGunlessdebug=True. The cost therefore grows with the number of flags in the project, not with the number of flags evaluated, and it is paid on the hot path of every server-side evaluation for a log line that is then thrown away.Observed impact
Measured on this branch's base (
main, 1.13.0) with 100 synthetic flags (two segments each, one condition, one bucket) in storage, evaluating a single flag with the default logger (WARNING), best of 5 × 5,000 calls on Python 3.14:evaluate_v2(user, {'flag-7'})mainAbout 99% of the evaluation time went into building a log message that was then discarded. We found this in production, where the repr was the largest cost of local evaluation in our request handlers. We currently work around it by swapping the storage's snapshot for a dict subclass with a constant-time
__repr__. We would like to drop that workaround.Change
The two
logger.debugcalls inevaluate_v2now use the standardlogginglazy formatting ("... %s", arg) instead of f-strings, so the arguments are only rendered when a handler actually emits the record. With DEBUG enabled, the output is identical:%sand an f-string placeholder both callstr().The other f-string debug calls in the SDK (
flag_config_updater,cohort_download_api,remote/client) run once per poll or per network fetch, not per evaluation, so this PR leaves them as they are to keep the diff minimal. Happy to convert them too if you prefer one style throughout.Tests (
tests/local/evaluate_logging_test.py, no network, client never started):WARNING,evaluate_v2evaluates correctly without rendering any flag config (EvaluationFlag.__repr__patched to raise). This test fails onmain.DEBUG, both records are still emitted with the same content (user JSON, every flag config, result).The 4
setUpClasserrors intests/local/client_test.pyandtests/local/client_eu_test.py(KeyError: 'API_KEY'/'EU_API_KEY') occur identically on unmodifiedmainin my environment. They need the CI secrets.Checklist
🤖 Generated with Claude Code
Note
Low Risk
Behavior change is limited to when log strings are formatted; DEBUG output is unchanged, and new unit tests cover the logging path.
Overview
Local evaluation hot path no longer builds DEBUG log strings on every
evaluate_v2call. The twologger.debuglines inlocal/client.pyswitch from f-strings to lazy%sformatting so flag configs and results are only rendered when DEBUG is actually enabled—addressing large per-request cost when the default logger level is WARNING.Tests in
tests/local/evaluate_logging_test.pyassert evaluation still works without rendering flag configs when DEBUG is off (via a patchedEvaluationFlag.__repr__) and that DEBUG output still includes user, flags, and results when enabled.CI pins the unit test workflow to
ubuntu-22.04instead ofubuntu-latest.Reviewed by Cursor Bugbot for commit dfdd86b. Bugbot is set up for automated code reviews on this repo. Configure here.