Accurate timing of functions in python

Question

I'm programming in python on windows and would like to accurately measure the time it takes for a function to run. I have written a function "time_it" that takes another function, runs it, and returns the time it took to run.

def time_it(f, *args):
    start = time.clock()
    f(*args)
    return (time.clock() - start)*1000

i call this 1000 times and average the result. (the 1000 constant at the end is to give the answer in milliseconds.)

This function seems to work but i have this nagging feeling that I'm doing something wrong, and that by doing it this way I'm using more time than the function actually uses when its running.

Is there a more standard or accepted way to do this?

When i changed my test function to call a print so that it takes longer, my time_it function returns an average of 2.5 ms while the cProfile.run('f()') returns and average of 7.0 ms. I figured my function would overestimate the time if anything, what is going on here?

One additional note, it is the relative time of functions compared to each other that i care about, not the absolute time as this will obviously vary depending on hardware and other factors.

Bursa

time-it allows you to add a decorator to any function to time it. It also accepts a logger name as a param so you can log the time pip install time-it disclaimer: I wrote the module – Caliche

Answer 1

Instead of writing your own profiling code, I suggest you check out the built-in Python profilers (profile or cProfile, depending on your needs): http://docs.python.org/library/profile.html

Laevo

Ignore me - that string is not a function name, it is a block of eval'd code. So you can use it for quick timing. This is the right answer. And in other news - "is not" is significantly quicker than "!=" - but may have other implications. – Severson

And off on that tangent - before using "is not" for anything clever - bear this in mind - #1392933 – Severson

The python profile docs say however: "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)." – Blighter

Answer 2

Use the timeit module from the Python standard library.

Basic usage:

from timeit import Timer

# first argument is the code to be run, the second "setup" argument is only run once,
# and it not included in the execution time.
t = Timer("""x.index(123)""", setup="""x = range(1000)""")

print t.timeit() # prints float, for example 5.8254
# ..or..
print t.timeit(1000) # repeat 1000 times instead of the default 1million

Cayman

i want my function to be called with different arguements, yet when i call t = timeit.Timer("f()", "from main import f") with different arguements and run t.timeit(10000) again, i get the same results though the different arguements should result in very different runtimes. – Bursa

Answer 3

You can create a "timeme" decorator like so

import time                                                

def timeme(method):
    def wrapper(*args, **kw):
        startTime = int(round(time.time() * 1000))
        result = method(*args, **kw)
        endTime = int(round(time.time() * 1000))

        print(endTime - startTime,'ms')
        return result

    return wrapper

@timeme
def func1(a,b,c = 'c',sleep = 1):
    time.sleep(sleep)
    print(a,b,c)

func1('a','b','c',0)
func1('a','b','c',0.5)
func1('a','b','c',0.6)
func1('a','b','c',1)

Chyou

+n for this answer. I wish there was such an option. Beauty is I can export the log results to an external file and add this wherever I need to! Thanks a zillion. – Beverly

This works great for non-recursive functions. For recursive functions, it returns a timing for each iteration of the function. – Leffler

Here's more refined version: #7371301 – Eboh

Answer 4

This code is very inaccurate

total= 0
for i in range(1000):
    start= time.clock()
    function()
    end= time.clock()
    total += end-start
time= total/1000

This code is less inaccurate

start= time.clock()
for i in range(1000):
    function()
end= time.clock()
time= (end-start)/1000

The very inaccurate suffers from measurement bias if the run-time of the function is close to the accuracy of the clock. Most of the measured times are merely random numbers between 0 and a few ticks of the clock.

Depending on your system workload, the "time" you observe from a single function may be entirely an artifact of OS scheduling and other uncontrollable overheads.

The second version (less inaccurate) has less measurement bias. If your function is really fast, you may need to run it 10,000 times to damp out OS scheduling and other overheads.

Both are, of course, terribly misleading. The run time for your program -- as a whole -- is not the sum of the function run-times. You can only use the numbers for relative comparisons. They are not absolute measurements that convey much meaning.

Barrick

Why the /1000? The method time.clock() returns seconds as a floating point value. If you expected it to return milliseconds, this would make sense, however dividing by 1000 converts to kiloseconds, a unit I have never seen used before. – Morly

@Morly milli / 1000 = micro, not kilo :) – Betts

@Betts He's suggesting that the resulting value is in seconds, e.g 1000 seconds. If you divide it by 1000, you get 1 "kiloseconds". – Secretary

@pixelgrease, /1000 because the function was executed 1000 times. So time is the average time it takes to execute the function once. – Geomancy

I would propose not to overwrite the module name 'time' with a variable called 'time' – Mirza

Answer 5

If you want to time a python method even if block you measure may throw, one good approach is to use with statement. Define some Timer class as

import time

class Timer:    
    def __enter__(self):
        self.start = time.clock()
        return self

    def __exit__(self, *args):
        self.end = time.clock()
        self.interval = self.end - self.start

Then you may want to time a connection method that may throw. Use

import httplib

with Timer() as t:
    conn = httplib.HTTPConnection('google.com')
    conn.request('GET', '/')

print('Request took %.03f sec.' % t.interval)

__exit()__ method will be called even if the connection request thows. More precisely, you'd have you use try finally to see the result in case it throws, as with

try:
    with Timer() as t:
        conn = httplib.HTTPConnection('google.com')
        conn.request('GET', '/')
finally:
    print('Request took %.03f sec.' % t.interval)

More details here.

Hyperbolic

Answer 6

This is neater

from contextlib import contextmanager

import time
@contextmanager
def timeblock(label):
    start = time.clock()
    try:
        yield
    finally:
        end = time.clock()
        print ('{} : {}'.format(label, end - start))



with timeblock("just a test"):
            print "yippee"

Democratic

Nice answer, simple and so far the only one I've found that allows you to send a label to the timer function. – Karlynkarma

Neat solution but a bit overly complicated. Spent an hour trying to figure out why time.sleep(10) only took 0.002 secs to execute according to this code. (btw, big difference between time.clock() and time.time() in python) – Cabbageworm

Answer 7

Similar to @AlexMartelli's answer

import timeit
timeit.timeit(fun, number=10000)

can do the trick.

Heterosis