Measure the total runtime of a function in a project

Question

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?

Answer 1

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.

Answer 2

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])