Skip to content

perf: format local evaluation debug logs lazily - #81

Open
yienyien wants to merge 1 commit into
amplitude:mainfrom
yienyien:perf-lazy-evaluate-debug-log
Open

yienyien wants to merge 1 commit into
amplitude:mainfrom
yienyien:perf-lazy-evaluate-debug-log

Conversation

@yienyien

@yienyien yienyien commented Oct 7, 2026 •

Copy link
Copy Markdown

Summary

LocalEvaluationClient.evaluate_v2 logs the whole flag config snapshot at DEBUG on every call:

# local/client.py
self.logger.debug(f"[Experiment] Evaluate: user={user} - Flags: {flag_configs}")

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: LocalEvaluationConfig sets the default logger to WARNING unless debug=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'})
main 0.383 ms
this PR 0.005 ms

About 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.debug calls in evaluate_v2 now use the standard logging lazy 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: %s and an f-string placeholder both call str().

self.logger.debug("[Experiment] Evaluate: user=%s - Flags: %s", user, flag_configs)
...
self.logger.debug("[Experiment] Evaluate Result: %s", variants)

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):

  • with the logger at WARNING, evaluate_v2 evaluates correctly without rendering any flag config (EvaluationFlag.__repr__ patched to raise). This test fails on main.
  • with the logger at DEBUG, both records are still emitted with the same content (user JSON, every flag config, result).

The 4 setUpClass errors in tests/local/client_test.py and tests/local/client_eu_test.py (KeyError: 'API_KEY' / 'EU_API_KEY') occur identically on unmodified main in my environment. They need the CI secrets.

Checklist

  • Does your PR title have the correct title format?
  • Does your PR have a breaking change?: no. Log messages are unchanged when DEBUG is enabled.

🤖 Generated with Claude Code


Note

Low Risk
Logging-only change on the evaluation path; DEBUG output is unchanged when enabled, and behavior is covered by new unit tests.

Overview
evaluate_v2 no longer builds DEBUG log strings on every call. The two logger.debug lines in LocalEvaluationClient.evaluate_v2 switch from f-strings to lazy %s formatting, so user, the full flag config snapshot, and results are only stringified when DEBUG is actually enabled.

New tests in evaluate_logging_test.py assert that with the logger at WARNING, evaluation still works without calling EvaluationFlag.__repr__, and that with DEBUG on the same two log records still appear with the expected content.

Reviewed by Cursor Bugbot for commit 8138f48. Bugbot is set up for automated code reviews on this repo. Configure here.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
@yienyien

yienyien commented Oct 7, 2026

Copy link
Copy Markdown
Author

This is a real pain point for us at WeWard, with a significant performance impact. We patched it locally and saw immediate benefits.

@yienyien
yienyien marked this pull request as ready for review October 12, 2026 14:51
@yienyien
yienyien requested a review from a team as a code owner October 12, 2026 14:51

This branch has not been deployed

No deployments
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