Python | Timing and Profiling the program

Problems – To find where the program spends its time and make timing measurements.

To simply time the whole program, it’s usually easy enough to use something like the Unix time command as shown below.

Code #1 : Command to time the whole program



filter_none

edit
close

play_arrow

link
brightness_4
code

bash % time python3 someprogram.py
real 0m13.937s
user 0m12.162s
sys 0m0.098s
bash %

chevron_right


On the other extreme, to have a detailed report showing what the program is doing, cProfile module is used.

filter_none

edit
close

play_arrow

link
brightness_4
code

bash % python3 -m cProfile someprogram.py

chevron_right


Output :

Ordered by: standard name
    ncalls tottime percall cumtime percall filename:lineno(function)
    263169 0.080 0.000 0.080 0.000 someprogram.py:16(frange)
    513 0.001 0.000 0.002 0.000 someprogram.py:30(generate_mandel)
    262656 0.194 0.000 15.295 0.000 someprogram.py:32()
    1 0.036 0.036 16.077 16.077 someprogram.py:4()
    262144 15.021 0.000 15.021 0.000 someprogram.py:4(in_mandelbrot)
    1 0.000 0.000 0.000 0.000 os.py:746(urandom)
    1 0.000 0.000 0.000 0.000 png.py:1056(_readable)
    1 0.000 0.000 0.000 0.000 png.py:1073(Reader)
    1 0.227 0.227 0.438 0.438 png.py:163()
    512 0.010 0.000 0.010 0.000 png.py:200(group)

More often than not, profiling the code lies somewhere in between these two extremes. For example, if one already knows that the code spends most of its time in a few selected functions. For selected profiling of functions, a short decorator can be useful.
 
Code #3: Using short decorator for selected profiling of functions

filter_none

edit
close

play_arrow

link
brightness_4
code

# abc.py
  
import time
from functools import wraps
  
def timethis(func):
    @wraps(func)
    def wrapper(*args, **kwargs):
        start = time.perf_counter()
        r = func(*args, **kwargs)
        end = time.perf_counter()
        print('{}.{} : {}'.format(func.__module__, func.__name__, end - start))
        return r
    return wrapper

chevron_right


To use the decorator, simply place it in front of a function definition to get timings from it as shown in the code below.
Code #4 :

filter_none

edit
close

play_arrow

link
brightness_4
code

@abc
def countdown(n):
    while n > 0:
    n -= 1
  
countdown(10000000)

chevron_right


Output :

__main__.countdown : 0.803001880645752

Code #5: Defining a context manager to time a block of statements.

filter_none

edit
close

play_arrow

link
brightness_4
code

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

chevron_right


Code #6: How the context manager works

filter_none

edit
close

play_arrow

link
brightness_4
code

with timeblock('counting'):
    n = 10000000
    while n > 0:
        n -= 1

chevron_right


Output :

counting : 1.5551159381866455

Code #7 : Using timeit module to study the performance of small code fragments

filter_none

edit
close

play_arrow

link
brightness_4
code

from timeit import timeit
print (timeit('math.sqrt(2)', 'import math'), "\n")
  
print (timeit('sqrt(2)', 'from math import sqrt'))

chevron_right


Output :

0.1432319980012835
0.10836604500218527

timeit works by executing the statement specified in the first argument a million times and measuring the time.



My Personal Notes arrow_drop_up

Check out this Author's contributed articles.

If you like GeeksforGeeks and would like to contribute, you can also write an article using contribute.geeksforgeeks.org or mail your article to contribute@geeksforgeeks.org. See your article appearing on the GeeksforGeeks main page and help other Geeks.

Please Improve this article if you find anything incorrect by clicking on the "Improve Article" button below.


Article Tags :

Be the First to upvote.


Please write to us at contribute@geeksforgeeks.org to report any issue with the above content.