Timing Python functions in two ways

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

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

StackExchange Code Review Q#107225, answer score: 3