Extra level in report when using decorator factories

[sebastian-correa]

I really like pyinstrument, it works like a charm! However, I'm facing an issue with the report when running decorated functions.

For example, the following code

import time
from functools import wraps


def timeit(message):
    def decorator(function):
        @wraps(function)
        def wrapper(*args, **kwargs):
            t1 = time.perf_counter()
            result = function(*args, **kwargs)
            t2 = time.perf_counter()
            print(f"{message} {t2 - t1}s")
            return result

        return wrapper

    return decorator


@timeit("You were done in")
def f(a, b, c):
    """TEST DOCSTRING"""
    time.sleep(1)
    return a + b + c

print(f.__name__)
print(f.__doc__)

for a, b, c in zip(range(10), range(10, 20), range(20, 30)):
    f(a, b, c)

has the following profile

were there's a wrapped level that is unexpected. print(f.__name__) prints f and print(f.__doc__) prints TEST DOCSTRING, which is fine.

If the decorator is changed to this

def timeit(message):
    @wraps
    def decorator(function):
        def wrapper(*args, **kwargs):
            t1 = time.perf_counter()
            result = function(*args, **kwargs)
            t2 = time.perf_counter()
            print(f"{message} {t2 - t1}s")
            return result

        return wrapper

    return decorator

the report looks good,

but print(f.__name__) prints decorator and print(f.__doc__) prints None, which is wrong.

Maybe this is an issue with my code, but these are the only 2 ways I imagine using wraps, as not using it also results in undesired behavior.

Edit: Running with

pyinstrument --renderer=html test.py

Edit 2: pyinstrument 4.4.0, on Python 3.10.8.

[joerick]

The first looks right, to me, though I'm a little fuzzy on how exactly wraps is working in the second output.

In the first, pyinstrument is accurately representing what is happening in the call stack - E.g. if wrapper was slow you'd want to know about it.

If you'd prefer to hide this frame, there's a new feature in recent versions of pyinstrument called 'traceback hide' where frames can be hidden. Check the changelog for details.

[sebastian-correa]

I guess that knowing if the decorator itself is slow could be useful in certain cases, yes. The __tracebackhide__ = True worked, I hadn't seen it documented.

Ended up being:

def timeit(message):
    def decorator(function):
        @wraps(function)
        def wrapper(*args, **kwargs):
            __tracebackhide__ = True
            t1 = time.perf_counter()
            result = function(*args, **kwargs)
            t2 = time.perf_counter()
            print(f"{message} {t2 - t1}s")
            return result

        return wrapper

    return decorator

Edit: you can now close the issue.