Contents

Python Performance Profiling

What is Profiling?

Python performance profiling

Profiling Definition?

  • Measuring the execution time.
  • Insight of run time performance of a given piece of code.
  • Frequently used to optimize execution time.
  • Used to analyze other characteristics such as memory consumption.

Why Profile?

You can use a profiler to answer questions like these:

  • Why is this program slow?
  • Why does it slow my computer to a crawl?
  • What is actually happening when this code executes?
  • Is there anything I can improve?
  • How much memory consumed by program?
  • How much time taken by each function execution?

Why You should care about Performance

  • “If You Can’t Measure It, You Can’t Manage It.”

  • Writing efficient code saves money in modern “cloud economy” (e.g. you need fewer VM instances).

  • Even if you don’t use clouds, a particular problem domain can have strict performance requirements (e.g. when you have to process a chunk of data in time before the next chunk arrives).

Available options for measuring Performance

Command Line

The time command is available in *nix systems.

1
$ time python some_program.py
1
2
3
real 0m4.536s
user 0m3.411s
sys 0m0.979s
  • Easy to use
  • Very limited information
  • Not very deterministic
  • Not available on Windows

Python time Module

time.time() statements

1
2
3
4
5
import time
initial_time = time.time()
time.sleep(1)
final_time = time.time()
print('Duration: {}'.format(final_time - initial_time))
1
Duration: 1.0898
  • Easy to use
  • Simple to understand
  • Very limited information
  • Not very deterministic
  • Manual code modification and analysis

Python timeit Module

1
2
3
4
5
6
import timeit

print('Plus:', timeit.timeit("['Hello world: ' + str(n) for n in range(100)]", number=1000))
print('Format:', timeit.timeit("['Hello world: {0}'.format(n) for n in range(100)]",
number=1000))
print('Percent:', timeit.timeit("['Hello world: %s' % n for n in range(100)]", number=1000))
  • Easy to use
  • Simple to understand
  • Measure execution time of small code snippets
  • Simple code only
  • Not very deterministic
  • Have to manually create runnable code snippets
  • Manual analysis

cProfile Module

Best approach: cProfile

  • Python comes with two profiling tools, profile and cProfile.
  • Both share the same API, and should act the same.
1
2
>>> import cProfile
>>> cProfile.run('2 + 2')
1
2
3
4
5
3 function calls in 0.000 seconds
Ordered by: standard name
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 0.000 0.000 <string>:1(<module>)
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler'}

Running a script with cProfile

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
# slow.py
import time
def main():
    sum = 0
    for i in range(10):
    sum += expensive(i // 2)
    return sum

def expensive(t):
    time.sleep(t)
    return t

if __name__ == '__main__':
    print(main())
1
python -m cProfile slow.py
 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
25 function calls in 20.030 seconds

Ordered by: standard name

ncalls tottime percall cumtime percall filename:lineno(function)
10 0.000 0.000 20.027 2.003 slow.py:11(expensive)
1 0.002 0.002 20.030 20.030 slow.py:2(<module>)
1 0.000 0.000 20.027 20.027 slow.py:5(main)
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler'objects}
1 0.000 0.000 0.000 0.000 {print}
1 0.000 0.000 0.000 0.000 {range}
10 20.027 2.003 20.027 2.003 {time.sleep}

cProfile sort by options

ncalls Total the number of calls of a function

tottime for the total time spent in the given function

cumtime is the cumulative time spent in this and all sub functions.

filename:lineno(function) provides the respective data of each function

cProfile result sorted by tottime

1
python -m cProfile -s tottime slow.py
 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
25 function calls in 20.015 seconds

Ordered by: **internal time**

ncalls **tottime** percall cumtime percall filename:lineno(function)
10 **20.015** 2.001 20.015 2.001 {built-in method time.sleep}
1 **0.000** 0.000 0.000 0.000 {built-in method builtins.print}
1 **0.000** 0.000 20.015 20.015 slow.py:6(main)
10 **0.000** 0.000 20.015 2.001 slow.py:13(expensive)
1 **0.000** 0.000 20.015 20.015 slow.py:3(<module>)
1 **0.000** 0.000 20.015 20.015 {built-in method builtins.exec}
1 **0.000** 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}

cProfile result sorted by ncalls

1
python -m cProfile -s ncalls slow.py
 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
25 function calls in 20.015 seconds

Ordered by: **call count**

**ncalls** tottime percall cumtime percall filename:lineno(function)
**10** 20.020 2.002 20.020 2.002 {built-in method time.sleep}
**10** 0.000 0.000 20.020 2.002 slow.py:13(expensive)
**1** 0.000 0.000 20.020 20.020 {built-in method builtins.exec}
**1** 0.000 0.000 0.000 0.000 {built-in method builtins.print}
**1** 0.000 0.000 20.020 20.020 slow.py:6(main)
**1** 0.000 0.000 20.020 20.020 slow.py:3(<module>)
**1** 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}

Easiest way to profile Python code

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
def main():
    sum = 0
    for i in range(10):
    sum += expensive(i // 2)
    return sum
def expensive(t):
    time.sleep(t)
    return t
    
if __name__ == '__main__':
     pr = cProfile.Profile()
     pr.enable()
     main()
     pr.disable()
     pr.print_stats()
 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
25 function calls in 20.030 seconds

Ordered by: standard name

ncalls tottime percall cumtime percall filename:lineno(function)
10 0.000 0.000 20.027 2.003 slow.py:11(expensive)
1 0.002 0.002 20.030 20.030 slow.py:2(<module>)
1 0.000 0.000 20.027 20.027 slow.py:5(main)
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler'objects}
1 0.000 0.000 0.000 0.000 {print}
1 0.000 0.000 0.000 0.000 {range}
10 20.027 2.003 20.027 2.003 {time.sleep}

We can also save the output!

1
2
3
4
5
6
if __name__ == '__main__':
pr = cProfile.Profile()
pr.enable()
main()
pr.disable()
**pr.dump_stats("profile.output")**

How do we use the profiling information?

pstats Module

  • You can use pstats to format the output in various ways.
  • pstats provides sorting options. ( calls, time, cumulative )
1
2
3
4
import pstats

p = pstats.Stats("profile.output")
p.strip_dirs().sort_stats("calls").print_stats()
1
2
3
4
5
6
7
8
9
23 function calls in 20.019 seconds

Ordered by: call count

ncalls tottime percall cumtime percall filename:lineno(function)
10 20.019 2.002 20.019 2.002 {built-in method time.sleep}
10 0.000 0.000 20.019 2.002 slow.py:14(expensive)
1 0.000 0.000 0.000 0.000 {built-in method builtins.print}
1 0.000 0.000 20.019 20.019 slow.py:7(main)

An easy way to visualize cProfile results

SNAKEVIZ library

1
pip install snakeviz
1
$ snakeviz profile.output
  • Snakeviz provides two ways to explore profiler data
  • Summaries Times
  • You can choose the sorting criterion in the output table

Python performance profiling

PyCallGraph library

1
pip install pycallgraph
1
$ pycallgraph graphviz -- python slow.py
  • Visual extension of cProfile.
  • Understand code structure and Flow
  • Summaries Times
  • Darker color represent more time spent.

Python performance profiling

Other profiling options

Line profiler

Memory profiler

Live Example

Python performance profiling

1
https://github.com/akkefa/pycon-python-performance-profiling/profiling-demo.ipynb

Thank you.