`serialize()` copies large Mapping locals in full before trimming to MAX_DATABAG_BREADTH

[Malkiz223]

How do you use Sentry?

Self-hosted/on-premise

Version

2.64.0

Steps to Reproduce

EventSerializer._serialize_node_impl's Mapping branch (sentry_sdk/serializer.py) copies the object in full before trimming it to MAX_DATABAG_BREADTH (10 by default) items:

elif isinstance(obj, Mapping):
    # Create temporary copy here to avoid calling too much code that
    # might mutate our dictionary while we're still iterating over it.
    obj = dict(obj.items())

    rv_dict: "Dict[str, Any]" = {}
    i = 0

    for k, v in obj.items():
        if remaining_breadth is not None and i >= remaining_breadth:
            self._annotate(len=len(obj))
            break
        ...

obj = dict(obj.items()) is O(len(obj)), not O(remaining_breadth). At most 10 key/value pairs ever get serialized, but the copy always walks the entire Mapping first.

This mostly does not matter for normal extra/tags payloads, but it becomes a real problem for local-variable capture (include_local_variables, on by default). Frame locals are whatever a function happens to hold at the time an exception is logged, whether or not that exception has anything to do with them. It's common for self in an instance method to reference a large in-memory structure (an LRU cache, a big dict, etc). We regularly have dict-like caches with up to a million entries in our services, and they routinely end up as frame locals on some unrelated exception that gets logged.

import logging
import time

import sentry_sdk
from sentry_sdk.integrations.logging import LoggingIntegration

sentry_sdk.init(
    dsn="http://foobar@127.0.0.1:1/1",
    default_integrations=False,
    integrations=[LoggingIntegration(event_level=logging.ERROR)],
)

logger = logging.getLogger("app")
logger.addHandler(logging.NullHandler())  # for convenience, optional - keeps the exception below from printing to the console


def raise_with_big_local(size):
    big_cache = {f"key_{i}": i for i in range(size)}  # not used below, just sits on the stack as a local
    start = time.perf_counter()
    try:
        1 / 0
    except ZeroDivisionError:
        logger.exception("boom")
    return time.perf_counter() - start


for size in (1_000, 10_000, 100_000, 1_000_000):
    elapsed = raise_with_big_local(size)
    print(f"dict size={size:>8}  capture took {elapsed * 1000:8.1f} ms")

Expected Result

Capturing an event with a large dict/Mapping local variable should cost about the same regardless of the dict's size, since only 10 of its keys ever end up in the serialized event.

Actual Result

Capture time scales with the size of the dict instead, even though big_cache is never touched:

dict size=    1000  capture took      1.9 ms
dict size=   10000  capture took      1.2 ms
dict size=  100000  capture took     14.8 ms
dict size= 1000000  capture took    274.8 ms

Where this bites in practice

We have big caches like this in production, and they end up as frame locals on exceptions we log. We process data in a loop, and a burst of such exceptions added up to roughly 30 seconds of synchronous work capturing them - and for that whole time, nothing else in the process could run. With the fix applied, each one costs a few milliseconds instead of close to a second.

Proposed fix

Only copy as many pairs as remaining_breadth (+1, so the existing truncation/annotation logic still sees that there's more) actually needs, falling back to a full copy when breadth is unbounded (None, or float("inf") for kept request bodies, since itertools.islice doesn't accept a float stop value):

elif isinstance(obj, Mapping):
    # Copy only as many pairs as we might keep - avoids O(len(obj)) work
    # when obj is huge (e.g. a large cache captured as a frame local),
    # while still protecting against mutation during iteration.
    obj_len = len(obj)
    if isinstance(remaining_breadth, int):
        obj = dict(islice(obj.items(), remaining_breadth + 1))
    else:
        obj = dict(obj.items())

    rv_dict: "Dict[str, Any]" = {}
    i = 0

    for k, v in obj.items():
        if remaining_breadth is not None and i >= remaining_breadth:
            self._annotate(len=obj_len)
            break
        ...

We monkey-patched the stock serializer with this fix in our production services. A parity test keeps its output identical to stock serialize() across event shapes, including the max_request_body_size="always" / unbounded-breadth path. The same benchmark with the fix applied:

dict size=    1000  capture took      2.1 ms
dict size=   10000  capture took      0.6 ms
dict size=  100000  capture took      0.8 ms
dict size= 1000000  capture took      1.0 ms

Capture time is now flat regardless of dict size.

If that would help, I can submit a PR with the fix and tests.

[linear-code]

PY-2600

[alexander-alderman-webb]

Thanks @Malkiz223 that's a fair performance optimization.

[Malkiz223]

Thanks for the quick reply! Want me to open a PR with the fix and tests?

[alexander-alderman-webb]

Yes, feel free to open a PR with the suggested improvement!
I don't think this performance improvement needs tests, since no functionality is changed.