perf(sdk-python): stop re-serializing oversized structured log records - #1028
Merged
Conversation
_bounded_mirror_line serialized the whole record with json.dumps before it
knew whether the record fit the mirror budget, and serialized it a second
time at the end to report original_size. A record carrying a multi-megabyte
string attribute therefore passed that payload to json.dumps twice, and every
size check did len(<str>.encode("utf-8")), materialising a throwaway
multi-megabyte bytes copy purely to count.
Three changes, all inside that one private method and the helpers next to it:
* _certainly_exceeds_budget is a shallow O(top-level keys + attributes) sum
over str/bytes payloads that skips the speculative whole-record dumps when
it can already prove the record is oversized. It is deliberately NOT a
recursive walker — a recursive lower-bound walk measured +318% on a fitting
14.7 KB record and never aborts early for int-heavy payloads. Nested
containers count as zero, so "False" means "unknown, serialize and measure",
and any exception falls back to that same path so a mirror line is never
dropped because the estimator misbehaved.
* _record_size reconstructs the full record size arithmetically from the
envelope plus the already-computed attributes size instead of re-encoding,
which removes the second whole-record dumps. It falls back to a plain dumps
when the record has no "attributes" key, because {**record,
"attributes": {}} would APPEND the key and overcount the envelope by 14
bytes in the reported original_size.
* _byte_len replaces len(x.encode("utf-8")) everywhere it was used only to
count; str.isascii() is an O(1) flag check on CPython's compact-unicode
representation, so the common case no longer allocates at all.
_json_key fixes a latent off-by-two while it is in here: json coerces non-str
dict keys (1 -> "1", True -> "true", None -> "null"), so measuring the raw key
undercut the attributes size by two bytes per non-str key and could push an
elision boundary the wrong way. bool is checked before int because
isinstance(True, int).
Output is unchanged: a 220-case differential harness (hand-picked edges plus
200 randomised records across budgets 256-16384) produces byte-identical lines
against the previous implementation, and the record handed to _dispatch_to_cp
is still only ever shallow-copied. Measured, mean of 5: one 5 MB str attribute
20.4 ms -> 9.0 ms (json.dumps calls carrying a >=1 MB payload: 2 -> 1),
200 x 50 KB attributes 46.2 ms -> 18.8 ms, and a fitting 14.7 KB record stays
at 0.18 ms.
Refs #985
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Regression tests for the mirror-line precheck, derived from the behavior contract rather than from the implementation: * a 5 MB str attribute passes a >=1 MB payload to json.dumps at most once (counting proxy around logger_module.json.dumps) — the deterministic guard that the whole-record dumps is really skipped; * a record that FITS the default 16384 budget is emitted byte-identically to a direct json.dumps and its nested values are never measured. The existing many-large-attributes test cannot catch a recursive precheck, because its first 50 KB attribute aborts the scan immediately; this one nests a str subclass whose isascii()/__len__ raise, which CPython's C json encoder never touches but a recursive walker would; * non-str attribute keys elide at the same per-attribute boundary and report an aggregate _elided size that matches json.dumps exactly (4030, not the 4024 the raw-key measurement produced); * a record with no "attributes" key reports its exact size in the minimal-record fallback rather than 14 bytes too many; * a payload that raises while being measured falls back to the full-dumps path, so the stdout line is still emitted instead of being dropped; * _json_key's coercion table (str / bool / None / float / __str__ fallback). No wall-clock assertion is added: the post-fix timing has only ~4.6x headroom and would be a CI flake source. Every existing structured-mirror test — including the exact <4002>/<4004> markers and the elapsed < 0.2 guard — passes unmodified. Refs #985 Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Both new guards passed against main's logger.py, so neither actually guarded the behaviour it was named for. - test_..._serializes_large_string_payload_at_most_once classified json.dumps calls by their *argument* (a >=1MB str). The redundant call this PR removes passes the record *dict*, not the 5 MB string, so both versions showed exactly one big-str argument. Count the *output* size instead: 1 on the branch, 2 on main, 2 with the precheck neutered. - test_..._fitting_nested_record_is_not_walked_recursively used a tripwire that raised AssertionError, but _certainly_exceeds_budget swallows every exception and falls back to the full-dumps path, so a recursive precheck silently emitted the byte-identical line the test asserted. Record the touches in a list and assert it stays empty; the byte-identical assertion is kept alongside it. Verified by mutation: with `return False` inserted at the top of _certainly_exceeds_budget the first test now fails (2 != 1), and with _shallow_payload_bytes made recursive over dicts/lists the second fails with 2800 recorded touches. Both were green before this change. Also applies `ruff format` to the one hunk in test_..._non_string_attribute_keys_have_exact_sizes that had drifted, so the file stays format-clean. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Contributor
Performance
✓ No regressions detected |
Contributor
📊 Coverage gateThresholds from
✅ Gate passedNo surface regressed past the allowed threshold and the aggregate stayed above the floor. |
Contributor
📐 Patch coverage gateThreshold: 80% on lines this PR touches vs
✅ Patch gate passedEvery surface whose lines were touched by this PR has patch coverage at or above the threshold. |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
The bounded stdout mirror added in #1002 still serialized the full structured record before deciding it was oversized — O(payload) CPU on the calling thread (~15 ms for a 5 MB
extrapayload), inside the tee lock. This change prechecks sizes from the record's top-level parts and reconstructs the envelope arithmetically, so an oversized record is never re-encoded and the emitted line is byte-identical to before.Why
Refs #985 — the remaining "blocks the event loop" cost of the mirror after v0.1.137's
AGENTFIELD_LOG_STDOUT/AGENTFIELD_LOG_MAX_LINE_BYTESwork.Changes
Validation contract
test_structured_mirror_is_bounded_valid_json_and_cp_receives_full_record,test_public_structured_logger_emits_only_bounded_json_linestest_structured_mirror_elides_oversized_non_dict_attributes,test_structured_mirror_non_string_attribute_keys_have_exact_sizestest_structured_mirror_fitting_nested_record_is_not_walked_recursively (byte-identical assert + newassert walked == []; fails with 2800 touches against a recursive-walker mutant),test_structured_mirror_many_large_attributes_stays_fasttest_structured_mirror_is_bounded_valid_json_and_cp_receives_full_record,test_structured_mirror_serializes_large_string_payload_at_most_once (asserts payload survives intact)test_structured_mirror_serializes_large_string_payload_at_most_once (counts json.dumps OUTPUT sizes: 1 on branch, 2 on main, 2 with the optimization neutered)test_structured_mirror_without_attributes_reports_exact_original_sizetest_structured_mirror_non_string_attribute_keys_have_exact_sizes,test_json_key_matches_json_dict_key_coercion (parametrized),test_json_key_falls_back_to_string_for_unknown_key_typeexisting precheck fallback tests in test_logger.py (suite green: 48/48 in the file, 2269 repo-wide)test_structured_stdout_disabled_skips_serialization,test_structured_stdout_can_be_disabledtest_structured_mirror_serializes_large_string_payload_at_most_once (total bytes serialized on the 5 MB case drops 10,000,201 -> 5,000,173)How it was tested
CI-literal gates in the worktree:
ruff check .,./scripts/run_pytest.sh(full sdk-python suite),./scripts/coverage-surface.sh sdk-python,./scripts/patch-coverage-gate.sh— ALL-PASS, patch gate ≥ 80 % on touched lines. Output byte-equality for the 5 MB oversized case is asserted in the tests.Notes / follow-ups
Non-blocking review findings kept as follow-ups:
sdk/python/agentfield/logger.py— Carried forward from the previous round (finding 5), unchanged and by design: for records with non-str attribute keys the aggregate fallback marker{"_elided": "<N bytes elided>"}now reports the exact serialized size,sdk/python/pyproject.toml— Carried forward from the previous round (finding 4), accepted as-is per that reviewer's own suggested_fix. The required patch-coverage check again reportssdk-python | 0 touched lines | — | no changesbecause `agentfie🤖 Generated with Claude Code