8
\$\begingroup\$

I recently wanted to find out which functions take which amount of time in a project, and calling a timer and printing the difference inside a function that is called multiple times does not scale well.

That's why I created my own little decorator function:

from timeit import default_timer as timer

time_in = dict()


def measure(func):

    def saveTime(identifier, time):
        global time_in
        if identifier not in time_in:
            time_in[identifier] = 0
        time_in[identifier] += time

    def measure_wrapper(*args, **kwargs):
        global time_in
        start = timer()
        value = func(*args, **kwargs)
        saveTime(func.__name__, timer() - start)
        return value

    return measure_wrapper

It works by prepending every function (or method) that should be measured with @measure and then printing the dict at the end of the main function. It works as intended. However, it adds a global variable and I'm sure there must already be a solution like it, I just haven't found it.

So, my questions are:

  • Is it possible to remove the global variable?
  • Is there already a solution like this in the standard libs?
\$\endgroup\$
1
  • 3
    \$\begingroup\$ Are you familiar with cProfile? \$\endgroup\$
    – Reinderien
    Jun 7 at 17:20

2 Answers 2

14
\$\begingroup\$

Adressing the question:

Is there already a solution like this in the standard libs?

Unless I am misinterpreting what you want exactly, there are profiling tools available in the standard library.

For instance, given the script

def fib(n):
    if n == 0:
        return 0
    elif n == 1:
        return 1
    else:
        return fib(n - 1) + fib(n - 2)


def factorial(n):
    if n == 0:
        return 1
    else:
        return n * factorial(n - 1)


def main():
    for i in range(30):
        fib(i)

    for i in range(30):
        factorial(i)


if __name__ == '__main__':
    main()

you can run:

python -m cProfile test.py

which gives

         4357055 function calls (64 primitive calls) in 1.484 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    1.484    1.484 test.py:1(<module>)
4356586/30    1.484    0.000    1.484    0.049 test.py:1(fib)
   465/30    0.000    0.000    0.000    0.000 test.py:11(factorial)
        1    0.000    0.000    1.484    1.484 test.py:18(main)
        1    0.000    0.000    1.484    1.484 {built-in method builtins.exec}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

This gives a few more statistics than your code currently does. There is also a Python API mentioned in the page that gives a way of using cProfile (or profile) in your python code.

However, if you are more interesting in benchmarks rather than profiling, according to the link above

Note: The profiler modules are designed to provide an execution profile for a given program, not for benchmarking purposes (for that, there is timeit for reasonably accurate results). This particularly applies to benchmarking Python code against C code: the profilers introduce overhead for Python code, but not for C-level functions, and so the C code would seem faster than any Python one.

\$\endgroup\$
0
9
\$\begingroup\$

The already accepted answer by Dair is better than what I am about to write here, however I think there is didactic value in trying to improve the code as written, so consider this a supplementary answer.

First, these smaller changes:

  1. Global variables that are not re-assigned inside a function do not require a global declaration.
  2. Consider using functools.wraps when writing decorators: this means that for example calling help(func) shows the expected results, rather than showing measure_wrapper.
  3. You can simplify your code by using a defaultdict.
from collections import defaultdict
from functools import wraps
from timeit import default_timer as timer

time_in = defaultdict(int)

def measure(func):
    @wraps(func)
    def measure_wrapper(*args, **kwargs):
        start = timer()
        value = func(*args, **kwargs)
        time_in[func.__name__] += timer() - start
        return value

    return measure_wrapper

Alright, so how do we use this function?

import mytimer  # or however your module is called

@mytimer.measure
def expensive_func(*args):
    ...  # do something that takes a lot of time

expensive_func(...)
print(mytimer.time_in['expensive_func'])

Can this be improved? Well, we have a problem in that if we define another expensive_func in a different module, they get counted as the same function, which probably isn't what you want!

A way to improve this is to use the wrapped function to index the dictionary:

        time_in[measure_wrapper] += timer() - start

which you can then use like this:

print(mytimer.time_in[expensive_func])
\$\endgroup\$

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.