Performance degradation after creating many classes with the same name

[MrCocoDev]

I suspect this is heavily related to #575, but my analysis suggests the issues showed up in 19.2.0 (2019-10-01) and that issue was created before the release went live.

I made a simple test harness to demonstrate the issue:

def create_class():
    @attr.s
    class MyClass(object):
        access_token = attr.ib()
        expires = attr.ib()
        refresh_token = attr.ib()
        user = attr.ib()
    
    return MyClass(
        access_token="string",
        expires=0,
        refresh_token="string",
        user="string",
    )

%timeit create_class()

I ran this over attrs versions: 18.2, 19.1, 19.2, 20.1, 21.1, and 21.2.

I collected the outputs:

[
    # Version num, timeit output, whether or not timeit warned for caching
    (18.2, "358 µs ± 4.47 µs per loop (mean ± std. dev. of 7 runs, 1000 loops each)", False),
    (19.1, "356 µs ± 1.8 µs per loop (mean ± std. dev. of 7 runs, 1000 loops each)", False),
    (19.2, "22 ms ± 9.5 ms per loop (mean ± std. dev. of 7 runs, 1000 loops each)", "The slowest run took 4.71 times longer than the fastest"),
    (20.1, "22.4 ms ± 9.85 ms per loop (mean ± std. dev. of 7 runs, 1000 loops each)", "The slowest run took 4.74 times longer than the fastest"),
    (21.1, "22.9 ms ± 9.74 ms per loop (mean ± std. dev. of 7 runs, 1000 loops each)", "The slowest run took 5.12 times longer than the fastest"),
    (21.2, "23.4 ms ± 10.5 ms per loop (mean ± std. dev. of 7 runs, 1000 loops each)", ""The slowest run took 4.91 times longer than the fastest"),
]

This suggests that something that went along with the 19.2 release is causing a performance leak. We noticed the issue because our CPU metrics started to spike when we upgraded attrs from version 18.2 directly to 21.2.

[euresti]

Looks like this change caused it (using git bisect):

eda9f2de6f7026039c3eee80297f0c95382d51d8 is the first bad commit
commit eda9f2de6f7026039c3eee80297f0c95382d51d8
Author: David Euresti <david@euresti.com>
Date:   Thu Aug 1 03:42:13 2019 -0700

    Make unique_filename not depend on repr. (#560)
    
    * Make unique_filename not depend on repr.
    
    For debugging purposes, when a method is created it needs to be put
    into a "filename".  This filename was generated using `repr(attrs)`
    however this meant that the filename could change every time the
    program was loaded depending on the whims of repr.  (In particular
    free functions and lambdas would include ids)
    
    This solves the problem by changing the name to be <attrs generated
    {method} {module}.{qualname}> If it should happen that the name is
    taken then -2 will be appended and incremented until a free filename
    is found.
    
    * Add tests
    
    * Fix tests and changelog

 changelog.d/560.change.rst |  2 ++
 src/attr/_make.py          | 66 ++++++++++++++++++++++++++++++++--------------
 tests/test_dunders.py      | 46 ++++++++++++++++++++++++++++++++
 3 files changed, 94 insertions(+), 20 deletions(-)
 create mode 100644 changelog.d/560.change.rst

[hynek]

That’s highly unfortunate and we probably should finally make benchmarks part of our workflow.

If someone is really good at profiling, I’m all eyes.

---

That said, I don’t think #575 is related to your benchmark (it talks only about creation of classes, not instantiation) and I also think it was more of a general observation facing a growing code base – not a timely regression.

[MrCocoDev]

It does look like this section here would take progressively longer with similarly named classes:

eda9f2d#diff-ca2708dc9bf685ad676dfaa594561d8fc5c18ae39a7a5bc517049ef3fce09541R1002

[hynek]

OMG @euresti thank you so much – that was fast!

[hynek]

Am I squinting correctly that this is a caused by an edge case where a lot of classes with the same fully-qualified name are created?

Is that really the case in your prod or are we chasing a red herring here possibly?

[euresti]

But is this issue actually real? It only happens in timeit because we're creating a class inside a method in a big loop. I don't think this is super common behavior.

If you do this:

@attr.s
class MyClass(object):
    access_token = attr.ib()
    expires = attr.ib()
    refresh_token = attr.ib()
    user = attr.ib()


def create_class():
    return MyClass(
        access_token="string",
        expires=0,
        refresh_token="string",
        user="string",
    )

The problem is gone.

Or if you really want to create a different class every time you can use make_class and give each a different name:

import attr
import secrets

def create_class():
    my_class = attr.make_class(
        f"MyClass{secrets.token_hex()}",
        dict(
            access_token=attr.ib(),
            expires=attr.ib(),
            refresh_token=attr.ib(),
            user=attr.ib(),
        ),
    )

    return my_class(
        access_token="string",
        expires=0,
        refresh_token="string",
        user="string",
    )

[MrCocoDev]

Am I squinting correctly that this is a caused by an edge case where a lot of classes with the same fully-qualified name are created?

Is that really the case in your prod or are we chasing a red herring here possibly?

It was really the case in our production environment until today when I finally tracked down the cause of the issue! 😅

[MrCocoDev]

It seems like it would be easy enough to support this, even though I agree that it is almost always avoidable. If instead of a -1, -2, it could just be a hash of the count, or something similarly random. Presumably that is okay? Albeit ugly.

[euresti]

Possible, though you might have to deal with multithreading issues then.

[MrCocoDev]

It seems like a SafeUUID (https://docs.python.org/3/library/uuid.html#uuid.SafeUUID) would fit the bill then? The same while True loop structure will work to handle the small chance of collisions.

[euresti]

I forgot to mention. The other requirement is that future runs generate the same "filename" This is to support tools that look at the stack trace.

[MrCocoDev]

I was wondering if that was going to be a requirement... That does complicate the issue a little. I will think on this a little.

[MrCocoDev]

So, this isn't pretty... but I think something along this line would work:

# This should probably be a calculated value to balance the weight of scanning keys
# versus looping over generated names
N = 1000  
unique_id = uuid.uuid4()
extra = ""
count = 1
file_prefix = f"<attrs generated {func_name} {module}.{cls}"

while True:
    unique_filename = f"{file_prefix}{extra}>"

    # To handle concurrency we essentially "reserve" our spot in
    # the linecache with a dummy line.  The caller can then
    # set this value correctly.
    cache_line = (1, None, (str(unique_id),), unique_filename)
    if (
        linecache.cache.setdefault(unique_filename, cache_line) == cache_line
    ):
        return unique_filename

    # Looks like this spot is taken. Try again.
    if count < N:
        count += 1
    else:
        # We have to sort to avoid potential forever loops if for example `MyClass-1` is created
        # by a joker 
        matching_file_names = sorted(
            (
                x
                for x
                in linecache.cache.keys()
                if x.startswith(file_prefix)
            ),
            key=lambda cache_key: int(cache_key[len(file_prefix) + 1:-1] or 0),
        )[-1]
        count = int(matching_file_names[len(file_prefix) + 1:-1])
        count += 1

    extra = "-{0}".format(count)

Other than running an internal cache for unique names per class, which would bloat with the more common case of many unique attr.s classes, I am not sure of how to reduce the name generation time which remains consistent across initializations.

[MrCocoDev]

Perhaps the easier solution is to just warn against using attr.s classes in a local scope? It seems innocuous enough to do:

def my_function():
    @attr.s
    class ConvenientDataShape:
         thing = attr.ib()
    return ConvenientDataShape(thing="thing")

That is essentially the code that broke our system. It was written in 2017 and in all that time every engineer who looked at it must have thought it looked fine enough to leave it.

[theY4Kman]

I mean, if the requirement is only that future runs generate the same filename, and not guarding against multiple versions of attrs installed at the same time all fighting for the same spots in the line cache, why not use a counter?

_unique_filename_counts = {}


def _generate_unique_filename(cls, func_name):
    """
    Create a "filename" suitable for a function being generated.
    """
    cls_name = getattr(cls, "__qualname__", cls.__name__)
    key = (func_name, cls.__module__, cls_name)

    count = _unique_filename_counts.get(key, 0) + 1
    _unique_filename_counts[key] = count

    extra = "-{0}".format(count) if count > 1 else ""
    unique_filename = "<attrs generated {0} {1}.{2}{3}>".format(*key, extra)

    cache_line = (1, None, (str(unique_id),), unique_filename)
    linecache.cache[unique_filename] = cache_line

    return unique_filename

The current implementation appears to be akin to iterating every item in a list to calculate the length, instead of just keeping a tally every time the list changes.

---

Creating a new class in every function call (especially one on a hot enough path to expose this perf problem) doesn't particularly seem wise, but it also seems entirely unexpected for these two snippets

def do_it():
    class Response:
        pass

    return Response()


def do_it_attr():
    @attr.s
    class Response:
        pass

    return Response()

... to differ in time by orders of magnitude

In [2]: %timeit do_it()
3.9 µs ± 28.3 ns per loop (mean ± std. dev. of 7 runs, 100000 loops each)

In [3]: %timeit do_it_attr()
The slowest run took 4.69 times longer than the fastest. This could mean that an intermediate result is being cached.
12.6 ms ± 5.47 ms per loop (mean ± std. dev. of 7 runs, 1000 loops each)