he profile module provides APIs for collecting and analyzing statistics about how Python source consumes processor resources.

Running the Profiler


In [1]:
import profile
def fib(n):
    if n <2:
        return n
    else:
        return fib(n-2) + fib(n-1)

def fib_seq(n):
    seq = []
    if n > 0:
        seq.extend(fib_seq(n-1))
    seq.append(fib(n))
    return seq

profile.run('print(fib_seq(20));print()')


[0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 987, 1597, 2584, 4181, 6765]

         57402 function calls (112 primitive calls) in 0.124 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        4    0.000    0.000    0.000    0.000 :0(acquire)
       21    0.000    0.000    0.000    0.000 :0(append)
        1    0.000    0.000    0.124    0.124 :0(exec)
       20    0.000    0.000    0.000    0.000 :0(extend)
        3    0.000    0.000    0.000    0.000 :0(getpid)
        3    0.000    0.000    0.000    0.000 :0(isinstance)
        2    0.000    0.000    0.000    0.000 :0(print)
        1    0.000    0.000    0.000    0.000 :0(setprofile)
        4    0.000    0.000    0.000    0.000 :0(urandom)
 57291/21    0.124    0.000    0.124    0.006 <ipython-input-1-10e2efe3abf3>:2(fib)
     21/1    0.000    0.000    0.124    0.124 <ipython-input-1-10e2efe3abf3>:8(fib_seq)
        1    0.000    0.000    0.124    0.124 <string>:1(<module>)
        4    0.000    0.000    0.000    0.000 iostream.py:180(schedule)
        3    0.000    0.000    0.000    0.000 iostream.py:285(_is_master_process)
        3    0.000    0.000    0.000    0.000 iostream.py:298(_schedule_flush)
        3    0.000    0.000    0.000    0.000 iostream.py:361(write)
        4    0.000    0.000    0.000    0.000 iostream.py:89(_event_pipe)
        1    0.000    0.000    0.124    0.124 profile:0(print(fib_seq(20));print())
        0    0.000             0.000          profile:0(profiler)
        4    0.000    0.000    0.000    0.000 threading.py:1062(_wait_for_tstate_lock)
        4    0.000    0.000    0.000    0.000 threading.py:1104(is_alive)
        4    0.000    0.000    0.000    0.000 threading.py:506(is_set)



In [2]:
import functools
import profile


@functools.lru_cache(maxsize=None)
def fib(n):
    # from literateprograms.org
    # http://bit.ly/hlOQ5m
    if n == 0:
        return 0
    elif n == 1:
        return 1
    else:
        return fib(n - 1) + fib(n - 2)


def fib_seq(n):
    seq = []
    if n > 0:
        seq.extend(fib_seq(n - 1))
    seq.append(fib(n))
    return seq

profile.run('print(fib_seq(20));print()')


[0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 987, 1597, 2584, 4181, 6765]

         132 function calls (112 primitive calls) in 0.001 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        4    0.000    0.000    0.000    0.000 :0(acquire)
       21    0.000    0.000    0.000    0.000 :0(append)
        1    0.000    0.000    0.001    0.001 :0(exec)
       20    0.000    0.000    0.000    0.000 :0(extend)
        3    0.000    0.000    0.000    0.000 :0(getpid)
        3    0.000    0.000    0.000    0.000 :0(isinstance)
        2    0.000    0.000    0.001    0.000 :0(print)
        1    0.000    0.000    0.000    0.000 :0(setprofile)
        4    0.000    0.000    0.000    0.000 :0(urandom)
     21/1    0.000    0.000    0.000    0.000 <ipython-input-2-65d58e243a01>:17(fib_seq)
       21    0.000    0.000    0.000    0.000 <ipython-input-2-65d58e243a01>:5(fib)
        1    0.000    0.000    0.001    0.001 <string>:1(<module>)
        4    0.001    0.000    0.001    0.000 iostream.py:180(schedule)
        3    0.000    0.000    0.000    0.000 iostream.py:285(_is_master_process)
        3    0.000    0.000    0.000    0.000 iostream.py:298(_schedule_flush)
        3    0.000    0.000    0.001    0.000 iostream.py:361(write)
        4    0.000    0.000    0.000    0.000 iostream.py:89(_event_pipe)
        1    0.000    0.000    0.001    0.001 profile:0(print(fib_seq(20));print())
        0    0.000             0.000          profile:0(profiler)
        4    0.000    0.000    0.000    0.000 threading.py:1062(_wait_for_tstate_lock)
        4    0.000    0.000    0.000    0.000 threading.py:1104(is_alive)
        4    0.000    0.000    0.000    0.000 threading.py:506(is_set)



In [3]:
profile.runctx('print(fib_seq(n)); print()', globals(), {'n':20})


[0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 987, 1597, 2584, 4181, 6765]

         111 function calls (91 primitive calls) in 0.001 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        4    0.000    0.000    0.000    0.000 :0(acquire)
       21    0.000    0.000    0.000    0.000 :0(append)
        1    0.000    0.000    0.001    0.001 :0(exec)
       20    0.000    0.000    0.000    0.000 :0(extend)
        3    0.000    0.000    0.000    0.000 :0(getpid)
        3    0.000    0.000    0.000    0.000 :0(isinstance)
        2    0.000    0.000    0.001    0.000 :0(print)
        1    0.000    0.000    0.000    0.000 :0(setprofile)
        4    0.000    0.000    0.000    0.000 :0(urandom)
     21/1    0.000    0.000    0.000    0.000 <ipython-input-2-65d58e243a01>:17(fib_seq)
        1    0.000    0.000    0.001    0.001 <string>:1(<module>)
        4    0.000    0.000    0.001    0.000 iostream.py:180(schedule)
        3    0.000    0.000    0.000    0.000 iostream.py:285(_is_master_process)
        3    0.000    0.000    0.000    0.000 iostream.py:298(_schedule_flush)
        3    0.000    0.000    0.001    0.000 iostream.py:361(write)
        4    0.000    0.000    0.000    0.000 iostream.py:89(_event_pipe)
        1    0.000    0.000    0.001    0.001 profile:0(print(fib_seq(n)); print())
        0    0.000             0.000          profile:0(profiler)
        4    0.000    0.000    0.000    0.000 threading.py:1062(_wait_for_tstate_lock)
        4    0.000    0.000    0.000    0.000 threading.py:1104(is_alive)
        4    0.000    0.000    0.000    0.000 threading.py:506(is_set)


Pstas:Saving and working with statistics


In [4]:
import cProfile as profile
import pstats

# Create 5 set of stats
for i in range(5):
    filename = 'profile_stats_{}.stats'.format(i)
    profile.run('print({}, fib_seq(20))'.format(i), filename)

# Read all 5 stats files into a single object
stats = pstats.Stats('profile_stats_0.stats')
for i in range(1, 5):
    stats.add('profile_stats_{}.stats'.format(i))

# Clean up filenames for the report
stats.strip_dirs()

# Sort the statistics by the cumulative time spent
# in the function
stats.sort_stats('cumulative')

stats.print_stats()


0 [0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 987, 1597, 2584, 4181, 6765]
1 [0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 987, 1597, 2584, 4181, 6765]
2 [0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 987, 1597, 2584, 4181, 6765]
3 [0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 987, 1597, 2584, 4181, 6765]
4 [0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 987, 1597, 2584, 4181, 6765]
Sat Sep  9 09:56:16 2017    profile_stats_0.stats
Sat Sep  9 09:56:16 2017    profile_stats_1.stats
Sat Sep  9 09:56:16 2017    profile_stats_2.stats
Sat Sep  9 09:56:16 2017    profile_stats_3.stats
Sat Sep  9 09:56:16 2017    profile_stats_4.stats

         577 function calls (477 primitive calls) in 0.002 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        5    0.000    0.000    0.002    0.000 {built-in method builtins.exec}
        5    0.000    0.000    0.002    0.000 <string>:1(<module>)
        5    0.000    0.000    0.002    0.000 {built-in method builtins.print}
       20    0.000    0.000    0.002    0.000 iostream.py:361(write)
       21    0.000    0.000    0.001    0.000 iostream.py:180(schedule)
       21    0.001    0.000    0.001    0.000 {built-in method posix.urandom}
    105/5    0.000    0.000    0.000    0.000 <ipython-input-2-65d58e243a01>:17(fib_seq)
       21    0.000    0.000    0.000    0.000 threading.py:1104(is_alive)
       20    0.000    0.000    0.000    0.000 iostream.py:298(_schedule_flush)
       21    0.000    0.000    0.000    0.000 threading.py:1062(_wait_for_tstate_lock)
       20    0.000    0.000    0.000    0.000 iostream.py:285(_is_master_process)
       21    0.000    0.000    0.000    0.000 {method 'acquire' of '_thread.lock' objects}
       21    0.000    0.000    0.000    0.000 iostream.py:89(_event_pipe)
      100    0.000    0.000    0.000    0.000 {method 'extend' of 'list' objects}
      105    0.000    0.000    0.000    0.000 {method 'append' of 'list' objects}
       21    0.000    0.000    0.000    0.000 threading.py:506(is_set)
       20    0.000    0.000    0.000    0.000 {built-in method posix.getpid}
       20    0.000    0.000    0.000    0.000 {built-in method builtins.isinstance}
        5    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}


Out[4]:
<pstats.Stats at 0x103397668>