CODEWITHSUNDEEP
pythonpython-3.x
Rollie
Rollie

Reputation: 4752

Is there a way to time a block of code that is executed many times?

Given a function like:

do_something_big():
  do_1()
  do_2()
  do_3()

It's easy to get the time it takes to run either do_something_big() or a single instance of do_1(). But assuming I have:

for _ in range(100000):
  do_something_big()

Is there an easy way to get how long 100,000 do_1's took? It's not so difficult to do - you'd just time each one and update some global state to keep track of aggregate time. But is there a utility already built that abstracts this for me?

Upvotes: 3

Views: 789

Answers (3)

Razzle Shazl
Razzle Shazl

Reputation: 1330

This is a decorator as the utility that you are looking for. Inspiration from here and here.

We create a decorator @timeit. We annotate our methods with this decorator which takes an optional n parameter. When n invocations reached, print a time metric for this method, otherwise print on every invocation.

from functools import wraps
from time import time
from collections import defaultdict
timedata = defaultdict(lambda : (0, 0.0))
    
def timeit(*decArgs, **decKw):
    def _timeit(func):
        @wraps(func)
        def timed(*args, **kw):
            name = func.__name__.upper()
            n = decKw.get('n', 1)
            if timedata[name][0] >= n:
                return func(*args, **kw)

            ts = time()
            result = func(*args, **kw)
            te = time()
            duration = int((te - ts) * 1000)
            
            cnt, ave = timedata[name]
            cnt += 1
            timedata[name] = (cnt, ((cnt-1) * ave + duration) / cnt)
            if n == cnt:
                print(f'{name:30s}: [{n:6d}x] -> {ave*cnt:7.3f}ms ({ave:6.3f}ms ave)')
                timedata[name] = (0, 0.0)
            return result
        return timed
    return _timeit

Usage:

from random import random

@timeit(n=100)
def do_1():
    sleep(random()/1000)

@timeit(n=3)
def do_something_big():
    for _ in range(200):
        do_1()

for _ in range(5):
    do_something_big()

Output:

DO_1                          : [   100x] ->  19.192ms ( 0.192ms ave)
DO_1                          : [   100x] ->  23.232ms ( 0.232ms ave)
DO_1                          : [   100x] ->  24.242ms ( 0.242ms ave)
DO_1                          : [   100x] ->  18.182ms ( 0.182ms ave)
DO_1                          : [   100x] ->  14.141ms ( 0.141ms ave)
DO_1                          : [   100x] ->  23.232ms ( 0.232ms ave)
DO_SOMETHING_BIG              : [     3x] -> 393.000ms (131.000ms ave)
DO_1                          : [   100x] ->  27.273ms ( 0.273ms ave)
DO_1                          : [   100x] ->  22.222ms ( 0.222ms ave)
DO_1                          : [   100x] ->  21.212ms ( 0.212ms ave)
DO_1                          : [   100x] ->  24.242ms ( 0.242ms ave)

Upvotes: 3

Jainil Patel
Jainil Patel

Reputation: 1324

Here is what I found on internet https://realpython.com/python-timer/: you’ll add optional names to your Python timer. You can use the name for two different purposes:

Looking up the elapsed time later in your code Accumulating timers with the same name To add names to your Python timer, you need to make two more changes to timer.py. First, Timer should accept the name as a parameter. Second, the elapsed time should be added to .timers when a timer stops:

class Timer: timers = dict()

def __init__(
    self,
    name=None,
    text="Elapsed time: {:0.4f} seconds",
    logger=print,
):
    self._start_time = None
    self.name = name
    self.text = text
    self.logger = logger

    # Add new named timers to dictionary of timers
    if name:
        self.timers.setdefault(name, 0)

# Other methods are unchanged

def stop(self):
    """Stop the timer, and report the elapsed time"""
    if self._start_time is None:
        raise TimerError(f"Timer is not running. Use .start() to start it")

    elapsed_time = time.perf_counter() - self._start_time
    self._start_time = None

    if self.logger:
        self.logger(self.text.format(elapsed_time))
    if self.name:
        self.timers[self.name] += elapsed_time

    return elapsed_time

Note that you use .setdefault() when adding the new Python timer to .timers. This is a great feature that only sets the value if name is not already defined in the dictionary. If name is already used in .timers, then the value is left untouched. This allows you to accumulate several timers:

>>> from timer import Timer
>>> t = Timer("accumulate")
>>> t.start()

>>> t.stop()  # A few seconds later
Elapsed time: 3.7036 seconds
3.703554293999332

>>> t.start()

>>> t.stop()  # A few seconds later
Elapsed time: 2.3449 seconds
2.3448921170001995

>>> Timer.timers
{'accumulate': 6.0484464109995315}

Upvotes: 0

eligolf
eligolf

Reputation: 1856

I would suggest using e.g. cProfile. This package will time each function in your code and output on a nice format:

import cProfile

pr = cProfile.Profile()
pr.enable()

run_your_program_here()

pr.disable()
pr.print_stats(sort='tottime')

The sort argument in the last line will sort the output based on your given option. You can read more about it here:

ncalls – how many times the function/method has been called (in case the same function/method is being called recursively then ncalls has two values eg. 120/20, where the first is the true number of calls, while the second is the number of direct calls)

tottime – the total time in seconds excluding the time of other functions/methods

percall – average time to execute function (per call)

cumtime – the total time in seconds includes the times of other functions it calls

percall – similar to the previous percall, however this one includes network delays thread sleeps etc…

In your case I would use 'tottime' and look at how much time do_1 took.

Upvotes: 6

Related Questions