Python time measure function

I want to create a python function to test the time spent in each function and print its name with its time, how i can print the function name and if there is another way to do so please tell me

def measureTime(a):
    start = time.clock() 
    a()
    elapsed = time.开发者_如何学Goclock()
    elapsed = elapsed - start
    print "Time spent in (function name) is: ", elapsed

First and foremost, I highly suggest using a profiler or atleast use timeit.

However if you wanted to write your own timing method strictly to learn, here is somewhere to get started using a decorator.

Python 2:

def timing(f):
    def wrap(*args):
        time1 = time.time()
        ret = f(*args)
        time2 = time.time()
        print '%s function took %0.3f ms' % (f.func_name, (time2-time1)*1000.0)
        return ret
    return wrap

And the usage is very simple, just use the @timing decorator:

@timing
def do_work():
  #code

Python 3:

def timing(f):
    def wrap(*args, **kwargs):
        time1 = time.time()
        ret = f(*args, **kwargs)
        time2 = time.time()
        print('{:s} function took {:.3f} ms'.format(f.__name__, (time2-time1)*1000.0))

        return ret
    return wrap

Note I'm calling f.func_name to get the function name as a string(in Python 2), or f.__name__ in Python 3.

After playing with the timeit module, I don't like its interface, which is not so elegant compared to the following two method.

The following code is in Python 3.

The decorator method

This is almost the same with @Mike's method. Here I add kwargs and functools wrap to make it better.

def timeit(func):
    @functools.wraps(func)
    def new_func(*args, **kwargs):
        start_time = time.time()
        result = func(*args, **kwargs)
        elapsed_time = time.time() - start_time
        print('function [{}] finished in {} ms'.format(
            func.__name__, int(elapsed_time * 1_000)))
        return result
    return new_func

@timeit
def foobar():
    mike = Person()
    mike.think(30)

The context manager method

from contextlib import contextmanager

@contextmanager
def timeit_context(name):
    start_time = time.time()
    yield
    elapsed_time = time.time() - start_time
    print('[{}] finished in {} ms'.format(name, int(elapsed_time * 1_000)))

For example, you can use it like:

with timeit_context('My profiling code'):
    mike = Person()
    mike.think()

And the code within the with block will be timed.

Conclusion

Using the first method, you can easily comment out the decorator to get the normal code. However, it can only time a function. If you have some part of code that you don't what to make it a function, then you can choose the second method.

For example, now you have

images = get_images()
big_image = ImagePacker.pack(images, width=4096)
drawer.draw(big_image)

Now you want to time the big_image = ... line. If you change it to a function, it will be:

images = get_images()
big_image = None
@timeit
def foobar():
    nonlocal big_image
    big_image = ImagePacker.pack(images, width=4096)
drawer.draw(big_image)

Looks not so great...What if you are in Python 2, which has no nonlocal keyword.

Instead, using the second method fits here very well:

images = get_images()
with timeit_context('foobar'):
    big_image = ImagePacker.pack(images, width=4096)
drawer.draw(big_image)

I don't see what the problem with the timeit module is. This is probably the simplest way to do it.

import timeit
timeit.timeit(a, number=1)

Its also possible to send arguments to the functions. All you need is to wrap your function up using decorators. More explanation here: http://www.pythoncentral.io/time-a-python-function/

The only case where you might be interested in writing your own timing statements is if you want to run a function only once and are also want to obtain its return value.

The advantage of using the timeit module is that it lets you repeat the number of executions. This might be necessary because other processes might interfere with your timing accuracy. So, you should run it multiple times and look at the lowest value.

Timeit has two big flaws: it doesn't return the return value of the function, and it uses eval, which requires passing in extra setup code for imports. This solves both problems simply and elegantly:

def timed(f):
  start = time.time()
  ret = f()
  elapsed = time.time() - start
  return ret, elapsed

timed(lambda: database.foo.execute('select count(*) from source.apachelog'))
(<sqlalchemy.engine.result.ResultProxy object at 0x7fd6c20fc690>, 4.07547402381897)

There is an easy tool for timing. https://github.com/RalphMao/PyTimer

It can work like a decorator:

from pytimer import Timer
@Timer(average=False)      
def matmul(a,b, times=100):
    for i in range(times):
        np.dot(a,b)        

Output:

matmul:0.368434
matmul:2.839355

It can also work like a plug-in timer with namespace control(helpful if you are inserting it to a function which has a lot of codes and may be called anywhere else).

timer = Timer()                                           
def any_function():                                       
    timer.start()                                         

    for i in range(10):                                   

        timer.reset()                                     
        np.dot(np.ones((100,1000)), np.zeros((1000,500)))
        timer.checkpoint('block1')                        

        np.dot(np.ones((100,1000)), np.zeros((1000,500)))
        np.dot(np.ones((100,1000)), np.zeros((1000,500)))
        timer.checkpoint('block2')                        
        np.dot(np.ones((100,1000)), np.zeros((1000,1000)))

    for j in range(20):                                   
        np.dot(np.ones((100,1000)), np.zeros((1000,500)))
    timer.summary()                                       

for i in range(2):                                        
    any_function()                                        

Output:

========Timing Summary of Default Timer========
block2:0.065062
block1:0.032529
========Timing Summary of Default Timer========
block2:0.065838
block1:0.032891

Hope it will help

Decorator method using decorator Python library:

import decorator

@decorator
def timing(func, *args, **kwargs):
    '''Function timing wrapper
        Example of using:
        ``@timing()``
    '''

    fn = '%s.%s' % (func.__module__, func.__name__)

    timer = Timer()
    with timer:
        ret = func(*args, **kwargs)

    log.info(u'%s - %0.3f sec' % (fn, timer.duration_in_seconds()))
    return ret

See post on my Blog:

post on mobilepro.pl Blog

my post on Google Plus

My way of doing it:

from time import time

def printTime(start):
    end = time()
    duration = end - start
    if duration < 60:
        return "used: " + str(round(duration, 2)) + "s."
    else:
        mins = int(duration / 60)
        secs = round(duration % 60, 2)
        if mins < 60:
            return "used: " + str(mins) + "m " + str(secs) + "s."
        else:
            hours = int(duration / 3600)
            mins = mins % 60
            return "used: " + str(hours) + "h " + str(mins) + "m " + str(secs) + "s."

Set a variable as start = time() before execute the function/loops, and printTime(start) right after the block.

and you got the answer.

Elaborating on @Jonathan Ray I think this does the trick a bit better

import time
import inspect

def timed(f:callable):
    start = time.time()
    ret = f()
    elapsed = 1000*(time.time() - start)
    source_code=inspect.getsource(f).strip('\n') 
    logger.info(source_code+":  "+str(elapsed)+" seconds")
    return ret

It allows to take a regular line of code, say a = np.sin(np.pi) and transform it rather simply into

a = timed(lambda: np.sin(np.pi))

so that the timing is printed onto the logger and you can keep the same assignment of the result to a variable you might need for further work.

I suppose in Python 3.8 one could use the := but I do not have 3.8 yet

Below is a Timer class that:

• Easy to use: use directly or as decorator function, < 100 lines
• Measures a lot: total calls, total time, average time, and std. deviation.
• Prints pretty time
• Thread-safe

This is how you use it:

# Create the timer
timer1 = Timer("a name", log_every=2)

# Use "with"
with timer1:
   print("timer1")

# Reuse as a decorator
@timer1
def my_func():
  print("my_func")

# Instantiate as a decorator
@Timer("another timer", log_every=1)
def my_func2():
  print("my_func2")

my_func()
my_func2()
my_func()

Below is the class

from datetime import datetime
import time, logging, math, threading
class Timer(object):
    '''A general timer class. Does not really belong in a judicata file here.'''
    def __init__(self, name, log_every = 1):
        self.name = name
        self.log_every = 1
        self.calls = 0
        self.total_time = 0
        self.total_squared_time = 0
        self.min, self.max = None, 0
        # Make timer thread-safe by storing the times in thread-local storage.
        self._local = threading.local()
        self._lock = threading.Lock()

    def __enter__(self):
        """Start a new timer"""
        self._local.start = datetime.utcnow()

    def __exit__(self, exc_type, exc_val, exc_tb):
        """Stop the timer, and report the elapsed time"""
        elapsed_time = (datetime.utcnow() - self._local.start).total_seconds()
        with self._lock:
            self.calls += 1
            self.total_time += elapsed_time
            if self.min == None or elapsed_time < self.min:
                self.min = elapsed_time
            if elapsed_time > self.max:
                self.max = elapsed_time
            self.total_squared_time += elapsed_time * elapsed_time
            if self.log_every and (self.calls % self.log_every) == 0:
                self.log()

    def __call__(self, fn):
        '''For use as a decorator.'''
        def decorated_timer_function(*args, **kwargs):
            with self:
                return fn(*args, **kwargs)
        return decorated_timer_function

    @classmethod
    def time_str(cls, secs):
        if isinstance(secs, six.string_types):
            try:
                secs = float(secs)
            except:
                return "(bad time: %s)"%secs
        sign = lambda x: x
        if secs < 0:
            secs = -secs
            sign = lambda x: ("-" + x)
        return sign("%d secs"%int(secs) if secs >= 120 else
                    "%.2f secs" % secs if secs >= 1 else
                    "%d ms" % int(secs * 1000) if secs >= .01 else
                    "%.2f ms" % (secs * 1000) if secs >= .0001 else
                    "%d ns" % int(secs * 1000 * 10000) if secs >= 1e-9 else
                    "%s" % secs)

    def log(self):
        if not self.calls:
            logging.info("<Timer %s: no calls>"%self.name)
            return
        avg = 1.0 * self.total_time / self.calls
        var = 1.0 * self.total_squared_time / self.calls - avg*avg
        std_dev = self.time_str(math.sqrt(var))
        total = self.time_str(self.total_time)
        min, max, avg = [self.time_str(t) for t in [self.min, self.max, avg]]
        logging.info("<Timer %s: N=%s, total=%s, avg=%s, min/max=%s/%s, std=%s>"
                     %(self.name, self.calls, total, avg, min, max, std_dev))

You can use timeit.default_timer along with a contextmanager:

from timeit import default_timer
from contextlib import contextmanager

@contextmanager
def timer():
    start_time = default_timer()
    try:
        yield
    finally:
        print("--- %s seconds ---" % (default_timer() - start_time))

Use it with with statement:

def looper():
    for i in range(0, 100000000):
        pass

with timer():
    looper()

Output:

--- 2.651526927947998 seconds ---

Here is a generic solution

def timed(fn):
    # make sure wherever u used this, imports will be ready
    from time import perf_counter
    from functools import wraps
    # wraps preserves the metadata of fn
    @wraps(fn)
    def inner(*args, **kwargs):
        start = perf_counter()
        result = fn(*args, **kwargs)
        end = perf_counter()
        elapsed = end - start
        args_ = [str(a) for a in args]
        kwargs_ = ["{0}={1}".format(k, v) for (k, v) in kwargs.items()]
        all_args = args_ + kwargs_
        args_str = ",".join(all_args)
        print("{0} ({1}) took {2:.6f} to run.".format(fn.__name__, args_str, elapsed))
        return result
    return inner

define a function:

@timed
def sum_up(a,b):
     return a+b

now call it:

sum_up(2,9)

For the case using timeit.timeit, if command

timeit.timeit(function_to_test, n=10000)

raise error ValueError: stmt is neither a string nor callable

or command

timeit.timeit('function_to_test', n=10000)

raise error name 'function_to_test' is not defined, then you need:

replace function_to_test or 'function_to_test' with str(function_to_test), that is

timeit.timeit(str(function_to_test), n=10000)

or if Python version >= 3.6, another way is using f string as

timeit.timeit(f'{function_to_test}', n=10000)

About version use lambda, i.e. timeit.timeit(lambda: function_to_test, n=10000), it work but, from my test, it take much longer time.

Here, is a concrete example:

import timeit

def function_to_test(n):
    s = 1
    for i in range(n):
        s += 1
    return s
    
print("time run function_to_test: ", timeit.timeit(str(function_to_test(1000000)), number=10000))
print("time run function_to_test: ", timeit.timeit(f'{function_to_test(1000000)}', number=10000))