Welcome, guest | Sign In | My Account | Store | Cart

This function annotates the a given function with its elapsed execution time in minutes, seconds, and milli seconds. The attricbute is a tuple named func_time. This function could also be used as a python 2.4 decorator.

Python, 30 lines
 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
import sys
import time

def timeit(f):
    """ Annotate a function with its elapsed execution time. """
    def timed_f(*args, **kwargs):
         t1 = time.time()

         try:
             f(*args, **kwargs)
         finally:
             t2 = time.time()

         timed_f.func_time = ((t2 - t1) / 60.0, t2 - t1, (t2 - t1) * 1000.0)

         if __debug__:
             sys.stdout.write("%s took %0.3fm %0.3fs %0.3fms\n" % (
                 f.func_name,
                 timed_f.func_time[0],
                 timed_f.func_time[1],
                 timed_f.func_time[2],
             ))

    return timed_f


def timeme():
    time.sleep(2)

timeme = timeit(timeme)

Example $ python -i example.py

>>> timeme()
timeme took 0.033m 1.999s 1999.470ms
>>> timeme.func_time
(0.033321801821390787, 1.9993081092834473, 1999.3081092834473)

This provides a relatively straight forward way of tracking elapsed execution time and using it when you need it.

5 comments

Edward Loper 16 years, 1 month ago  # | flag

Re: Use function annotation to track elapsed execution time. Here's a slight extension that will give you the min, max, and average time spent in a function. It might be useful for very simplistic profiling.

def timeit(f):
    """ Annotate a function with its elapsed execution time. """
    def timed_f(*args, **kwargs):
        t1 = time.time()

        try:
            f(*args, **kwargs)
        finally:
            t2 = time.time()

        dt = t2-t1
        timed_f.func_maxtime = max(dt, getattr(timed_f, 'func_maxtime', 0))
        timed_f.func_mintime = min(dt, getattr(timed_f, 'func_mintime',
                                               sys.maxint))
        timed_f.func_numcalls = getattr(timed_f, 'func_numcalls',0)+1
        timed_f.func_avgtime = ((dt+((timed_f.func_numcalls-1) *
                                     getattr(timed_f, 'func_avgtime',0))) /
                                timed_f.func_numcalls)

    return timed_f

def print_functimes(f):
    print 'Avg running time: %f secs' % f.func_avgtime
    print 'Max running time: %f secs' % f.func_maxtime
    print 'Min running time: %f secs' % f.func_mintime
    print 'Number of calls: %d' % f.func_numcalls

(BTW, to be a friendly decorator, it's probably a good idea to copy the __doc__, __name__, etc attributes from f to timed_f.)

Walter Brunswick 16 years, 1 month ago  # | flag

How exactly is this function supposed to be called?

Matteo Bertini 15 years, 8 months ago  # | flag

Add a return value to timed_f. The timed_f function doesn't return any value.

Adding a:

res = f(...)

and a

return res

at the end solves the problem of timing a function that returns something.

pablo E Adames 9 years, 4 months ago  # | flag

Below my two cent contribution from using this otherwise very good recipe.

The change allows it to actually pass arguments to the function f and it returns the function timed_f with the tuple func_time as an attribute from which you can extract the actual time in m, s, or ms.

def timeit(f, *args, **kargs):
    def timed_f(args, *kwargs):
        t1 = time.time()
        try:
            f(args, *kwargs)
        finally:
            t2 = time.time()

        timed_f.func_time = ((t2 - t1) / 60.0, t2 - t1, (t2 - t1) * 1000.0)

        if __debug__:
            sys.stdout.write("%s took %0.3fm %0.3fs %0.3fms\n" % (
                f.func_name,
                timed_f.func_time[0],
                timed_f.func_time[1],
                timed_f.func_time[2],
            ))
        return timed_f
    return timed_f(args, *kargs)
pablo E Adames 9 years, 4 months ago  # | flag

For the function that collects statistics here is my modification so I could actually accumulate values:

def timeit2(results, f, *args, **kargs):
    def timed_f(results, f, args, *kwargs):
        t1 = time.time()
        try:
            f(args, *kwargs)
        finally:
            t2 = time.time()
        dt = t2-t1
        timed_f.func_current_exec_time = dt
        if results==None:
            timed_f.func_maxtime = max(dt, getattr(timed_f, 'func_maxtime', 0))
            timed_f.func_mintime = min(dt, getattr(timed_f, 'func_mintime',
                                                   sys.maxint))
            timed_f.func_numcalls = getattr(timed_f, 'func_numcalls',0)+1
            timed_f.func_avgtime = ((dt+((timed_f.func_numcalls-1) *
                                         getattr(timed_f, 'func_avgtime',0))) /
                                    timed_f.func_numcalls)
        else:
            timed_f.func_maxtime = max(dt, results.func_maxtime)
            timed_f.func_mintime = min(dt, results.func_mintime)
            timed_f.func_numcalls = results.func_numcalls+1
            timed_f.func_avgtime = ((dt+((results.func_numcalls)* /
                                    results.func_avgtime)) / 
                                    timed_f.func_numcalls)
    return timed_f
return timed_f(results,f,args,*kargs)

Usage assuming there is a function called FuncToTime() we want quickly profle:

def mytest():
    f=None
    for i in xrange(10):
        f=timeit2(f,FuncToTime)
    print_functimes(f)

If arguments need to be passed just add them like so:

def mytest():
    f=None
    for i in xrange(10):
        f=timeit2(f,FuncToTime, i)
    print_functimes(f)
Created by John Pywtorak on Mon, 19 Sep 2005 (PSF)
Python recipes (4591)
John Pywtorak's recipes (2)

Required Modules

Other Information and Tasks