Timing Python functions in two ways

Question

When reviewing questions here on Code Review SE, I sometimes find my self wanting to test different functions in order to do a performance review. However since I'm inherently lazy, I wonder what is the most effective or best practice for doing timing of functions in Python?

To make this an apt question for Code Review here are my two current, working solutions, which I want reviewed for unintended performance penalties, shortness and readability of code. Will welcome better suggestions on how to improve and ease my testing regime.

The difference of the two test methods are:

# From do_timing_ver1

test_case = "from {0} import {1}; {1}({2}, {3})"
...
elapsed_time = timeit.timeit(test_case.format(__name__, test_function, A, B),
                                             number=TEST_RUNS)

# From do_timing_ver2
timer = timeit.Timer(partial(test_function, A, B))
elapsed_time = timer.timeit(TEST_RUNS)

And here is the full code, with some dummy functions to be tested:

from functools import partial
from random import randint
import timeit
import time

def milli_sleep(milli_seconds):
   time.sleep(milli_seconds / 1000.0)

def foo(a, b):
   # Do stuff related to a and b, possibly calling other methods
   # I.e. OPs original code
   milli_sleep(800)
   pass


def bar(a, b):
   # Do stuff related to a and b, possibly calling other methods
   # I.e. my solution
   milli_sleep(200)


def baz(a, b):
   # Do stuff related to a and b, possibly calling other methods
   # I.e. some other solution
   milli_sleep(400)


def do_timing_ver1():

    A = [1, 2, 3, 4]
    B = False
    TEST_RUNS = 1

    test_case = "from {0} import {1}; {1}({2}, {3})"

    print('Timing version 1')
    for test_function in ('foo',
                          'bar',
                          'baz',
                         ):

        print ('\nTesting {}'.format(test_function))


        elapsed_time = timeit.timeit(test_case.format(__name__, test_function, A, B),
                                             number=TEST_RUNS)

        print('    execution time: {:,.4f} seconds'.format(elapsed_time))



def do_timing_ver2():

    A = [1, 2, 3, 4]
    B = False
    TEST_RUNS = 1

    print('\n\nTiming version 2')
    for test_function in (foo,
                          bar,
                          baz,):

        print('\nTesting {}'.format(test_function.__name__))

        timer = timeit.Timer(partial(test_function, A, B))

        elapsed_time = timer.timeit(TEST_RUNS)
        print('   execution time: {:,.4f}s'.format(elapsed_time))


def main():
    do_timing_ver1()
    do_timing_ver2()

if __name__ == '__main__':
    main()

On a sidenote

The optimal solution would be for me to include a personal library, and the do a call like:

from utilities import time_performance

time_performance(['foo', 'bar', 'baz'], A, B)

(Added) Using a module

A newly written module, utilities.py, for the sidenote to work is:

def time_performance(test_runs, module_name, functions, *params):
    """Time execution of all the <functions> passing all parameters given"""


    test_case = 'from {0} import {1}; {1}({2})'

    print('\n\nTime performance')
    for test_function in functions:

        print ('\nTesting {}'.format(test_function))


        elapsed_time = timeit.timeit(test_case.format(module_name,
                                                      test_function,
                                                      ', '.join(repr(param) for param in params)),
                                             number=test_runs)

        print('    execution time: {:,.4f} seconds'.format(elapsed_time))

which can be called with:

time_performance(1, __name__, ['foo', 'bar', 'baz'], [1, 2, 3, 4], False)

In other words, a few extra options, and I really don't like depending on the repr() function to pass arguments. But it does indeed work in my test case.

Reiteration of review issues

• Can you review either version, or suggest even better version for timing similar functions with parameters?
• Can you review or improve the module version of such a performance tester?

Answer 1

Your code

Unintended consequence : What happens to your timer if timeit fails because of an exception thrown ? Do you still want your timer ?

(Ipython) magic !

It seems you're just wrapping around timeit (which is cool on functionality, but too verbose for me) : if you're prototyping with ipython lying around, you can just use %timeit test_case.format(__name__, test_function, A, B)

This is simpler to type, and can be tuned (number of repetitions ...) just like the timeit module (which it calls under the hood). See ipython Magic for that.

Lprof

Best practice is using lprof which gives you a line by line timing. But lprof is a profiler through which you run your calls, rather than a timer you can trigger.

Extending on ipython, you can even call %lprun as a magic if you install it correctly. See the Github page for more info.

My solution

I needed in my last project a way of logging the performance of expensive calls. I used a class and the with statement, which can be called like so :

with Functimer("Expensive Function call"):
    foo = expensiveFunction(bar)

and shows up in log as

Starting expensive function call ...
Expensive function call over in 24s

You can use the info extra parameter to trigger the function timer as a logging.info rather than logging.debug (default).

Limitation is it uses directly the logging module, disregarding the current logger, but that can be worked around.

If you want to repeat the call for averaging, there might be a way of doing that (but I don't see it just now).

I got the idea from a python recipe, I'll try to find it again. Here's the code

class FuncTimer:
""" Convenience class to time function calls

Use via the "with" keyword ::

    with Functimer("Expensive Function call"):
        foo = expensiveFunction(bar)

A timer will be displayed in the current logger as `"Starting expensive function call ..."`
then when the code exits the with statement, the log will mention `"Finished expensive function call in 28.42s"`

By default, all FuncTimer log messages are written at the `logging.DEBUG` level. For info-level messages, set the
`FuncTimer.info`  argument to `True`::

    with Functimer("Expensive Function call",info=True):
        foo = expensiveFunction(bar)
"""

def __init__(self, funcName, info=False):
    self.funcName = funcName
    self.infoLogLevel = info

def __enter__(self):
    if self.infoLogLevel:
        logging.info("Starting {} ...".format(self.funcName))
    else:
        logging.debug("Starting {} ...".format(self.funcName))
    self.start = time.clock()
    return self

def __exit__(self, *args):
    self.end = time.clock()
    self.interval = self.end - self.start
    if self.infoLogLevel:
        logging.info("{} over in {}s".format(self.funcName, self.interval).capitalize())
    else:
        logging.debug("{} over in {}s".format(self.funcName, self.interval).capitalize())

Answer 2

This question hasn't received the amount of attention I was hoping for, but my need for timing stuff has led me to find some alternative solutions on how to do it. In general I've been using three variations of timings lately:

1. %timeit in an IPython shell
2. for loop using %timeit in an IPython shell
3. My custom method

I'll cover all of these with a little more detail in this answer.

Plain %timeit

In most test cases related to Code Review answers I start of with the original code, review it and write some refactored code. In some cases other answers suggests other implementations, and then I copy them into the same file.

To keep the solutions apart I've adapted a procedure of creating main_org(), main() (or main_holroy()) for my solution, and then main_xxxx() for other solution where the xxxx is the username of the answererer. This allows me to have the same interface to all of the main testing method of each variation, and I've typically made them with two versions: One with output for verification of correctness, and one version without output for execution timing.

When these are made I typical have code like the following:

def main(text=None, with_output=False):
    if with_output:
        print("Text is: {}".format(text))

    result = do_something(text)

    if with_output:
        print("Result is: {}".format(result))

And then I can do this in IPython:

In [8]: %timeit main_v2("My example text")
100000 loops, best of 3: 10.4 µs per loop

The %timeit call will then automatically decide how many rounds it will run with a few repetitions, and present the lowest execution time of all these executions.

Using %timeit in a loop

A natural extension for me was then to do all of my variations in one go, and therefore I started doing stuff like this:

In [9]: for test_main in (main, main_org):
   ...:     print("Testing {}:".format(test_main.__name__, ))
   ...:     %timeit test_main("My example text")
   ...:  
Testing main:
100000 loops, best of 3: 11.5 µs per loop
Testing main_org:
100000 loops, best of 3: 18.1 µs per loop

This still has the advantage of using the automatic detection of %timeit for determining how many rounds to do, and still get reliable results, whilst still maintaining a simple structure to calling it.

My custom method

Even though it worked nicely, I didn't really like my original test method since I had to decide how many runs it had to do, and since it summed up all the times into a total running time (instead of a time per loop). In addition you had to make the test function names, i.e. main_xxxx into strings. So I changed it into the following:

TEST_PERFORMANCE_MINIMUM_TIME = 0.3 
TEST_PERFORMANCE_BOTTOM_COUNT = 3

def time_performance(functions, *params):
    """Time execution for all the <functions> with optional <params>.

    NB! parameters needs to be str'ified and global variables in
    callers module.
    """

    max_name_length = max(len(function.__name__) for function in functions)

    SETUP_PATTERN = "from {} import {}"#.format(imports, "{}") #.format(imports[0], ', '.join(imports[1:]))
    function_parameters = ', '.join(params) if params else ''

    print("\n\nExecution times:\n")

    for function in functions:
        # Reset timers and temporary variables
        loop_times = []
        elapsed_time = 0.0
        test_runs = 1
        total_runs = 0
        function_name = function.__name__  

        gc.collect()

        test_function = '{}({})'.format(function_name, function_parameters)
        test_setup = SETUP_PATTERN.format(function.__module__,
                                          ', '.join([function_name] + list(params)))

        # To preserve some accuracy, ensure a run time of at least MINIMUM_TESTTIME
        while elapsed_time < TEST_PERFORMANCE_MINIMUM_TIME:
            loop_times.extend(timeit.repeat(test_function, test_setup,
                                            repeat=test_runs, number=1))

            total_runs += test_runs
            # If elapsed time not long enough, execute more test runs
            elapsed_time = sum(loop_times)
            if elapsed_time < TEST_PERFORMANCE_MINIMUM_TIME:
                test_runs = 9 * total_runs

        # Output final result for function in milliseconds.
        loop_times = sorted(loop_times)
        bottom_avg = sum(loop_times[:TEST_PERFORMANCE_BOTTOM_COUNT])/len(loop_times[:TEST_PERFORMANCE_BOTTOM_COUNT])

        print("    {:<{}}: {:6} loops".format(function_name, max_name_length, len(loop_times)),
              "avg(min[:{}]): {:8,.2f} ms".format(TEST_PERFORMANCE_BOTTOM_COUNT, bottom_avg * 1000), 
              "max: {:8,.2f} ms".format(max(loop_times) * 1000), 
#              "min: {:8,.2f} ms".format(min(loop_times) * 1000),
#              "avg: {:8,.2f} ms".format(sum(loop_times)/len(loop_times) * 1000),
              sep = ', '
              )

Just for test purposes I created three main functions, which called a test function with time.sleep(x) where x as 1 ms, 10 ms and 100ms. This resulted in the following output:

main_1  :   1000 loops, avg(min[:3]):     1.03 ms, max:     1.36 ms
main_10 :    100 loops, avg(min[:3]):    10.10 ms, max:    12.59 ms
main_100:     10 loops, avg(min[:3]):   101.91 ms, max:   105.06 ms

Note that contrary to %timeit this function returns the average of the 3 fastest times (i.e TEST_PERFORMANCE_BOTTOM_COUNT) and the slowest time. And if you want the other times, you can uncomment corresponding lines from bottom of the function. For me these two times are the most interesting, as the max time indicates if there are cache effects in play, and the bottom 3 averages out load on my computer a little.

Also note that the code needs to have from __future__ import print_function in order for the magic join in the last print statement to work properly if you use it in Python 2.

Conclusion

With these three variations I'm now able to have the following code at the end of a review script:

if __name__ == '__main__':

   doctest.testmod()   # If I want to execute the doctests

   mains = [main_1, main_10, main_100]

   for main in mains:
       main(with_output=True)

   test_performance(mains)

And this would provide me with a proper run of any doctests if present, a run with output to verify correctness of the different main methods, and a test performance run giving me output ready for inclusion in code reviews. Or for various other runs using IPython I can either use the different main methods, or I could use the newly created mains list of main methods.