Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

The @profile decorator will profile another decorator when chaining multiple decorators into a function. #373

Open
stenbein opened this issue Nov 3, 2022 · 1 comment

Comments

@stenbein
Copy link

stenbein commented Nov 3, 2022

Stacking multiple decorators together will result in unexpected behavior. A trivial example:

from functools import wraps
from random import random
import time

from memory_profiler import profile

def timeit(f):
    @wraps(wrapped=f)
    def wrapper(*args, **kw):
        ts = time.time()
        result = f(*args, **kw)
        te = time.time()
        print(f'func: {f.__name__} took: {te-ts:2.4f} sec')
        return result

    return wrapper


@profile
@timeit
def to_profile(n):
    arr = [random() for i in range(n)]
    return sum(arr)


to_profile(1_000)

What I expect to see:

Line #    Mem usage    Increment  Occurrences   Line Contents
=============================================================
    20     48.8 MiB     48.8 MiB           1   @timeit
    21                                         @profile
    22                                         def to_profile(n):
    23     48.8 MiB      0.0 MiB        1003       arr = [random() for i in range(n)]
    24     48.8 MiB      0.0 MiB           1       return sum(arr)

What we actually get:

Line #    Mem usage    Increment  Occurrences   Line Contents
=============================================================
     9     49.0 MiB     49.0 MiB           1       @wraps(wrapped=f)
    10                                             def wrapper(*args, **kw):
    11     49.0 MiB      0.0 MiB           1           ts = time.time()
    12     49.0 MiB      0.0 MiB           1           result = f(*args, **kw)
    13     49.0 MiB      0.0 MiB           1           te = time.time()
    14     49.0 MiB      0.0 MiB           1           print(f'func: {f.__name__} took: {te-ts:2.4f} sec')
    15     49.0 MiB      0.0 MiB           1           return result

I realized while checking this that the sample timeit decorator has the same issue and is timing the @profile rather than the underlying to_profile.

@stenbein
Copy link
Author

stenbein commented Nov 3, 2022

Possible partial solution: Decorators which use functools.wraps annotate the function object with wrapped property which points to the wrapped target. Recursively checking for the wrapper and replacing the function in each case correctly profiles the target function. See mock https://github.com/stenbein/memory_profiler/tree/stacked-decorators

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

No branches or pull requests

1 participant