+++ /dev/null
-.. highlight:: cython
-
-.. _profiling:
-
-*********
-Profiling
-*********
-
-This part describes the profiling abilities of Cython. If you are familiar
-with profiling pure Python code, you can only read the first section
-(:ref:`profiling_basics`). If you are not familiar with python profiling you
-should also read the tutorial (:ref:`profiling_tutorial`) which takes you
-through a complete example step by step.
-
-.. _profiling_basics:
-
-Cython Profiling Basics
-=======================
-
-Profiling in Cython is controlled by a compiler directive.
-It can either be set either for an entire file or on a per function
-via a Cython decorator.
-
-Enable profiling for a complete source file
--------------------------------------------
-
-Profiling is enable for a complete source file via a global directive to the
-Cython compiler at the top of a file::
-
- # cython: profile=True
-
-Note that profiling gives a slight overhead to each function call therefore making
-your program a little slower (or a lot, if you call some small functions very
-often).
-
-Once enabled, your Cython code will behave just like Python code when called
-from the cProfile module. This means you can just profile your Cython code
-together with your Python code using the same tools as for Python code alone.
-
-Disabling profiling function wise
-------------------------------------------
-
-If your profiling is messed up because of the call overhead to some small
-functions that you rather do not want to see in your profile - either because
-you plan to inline them anyway or because you are sure that you can't make them
-any faster - you can use a special decorator to disable profiling for one
-function only::
-
- cimport cython
-
- @cython.profile(False)
- def my_often_called_function():
- pass
-
-
-.. _profiling_tutorial:
-
-Profiling Tutorial
-==================
-
-This will be a complete tutorial, start to finish, of profiling python code,
-turning it into Cython code and keep profiling until it is fast enough.
-
-As a toy example, we would like to evaluate the summation of the reciprocals of
-squares up to a certain integer :math:`n` for evaluating :math:`\pi`. The
-relation we want to use has been proven by Euler in 1735 and is known as the
-`Basel problem <http://en.wikipedia.org/wiki/Basel_problem>`_.
-
-
-.. math::
- \pi^2 = 6 \sum_{k=1}^{\infty} \frac{1}{k^2} =
- 6 \lim_{k \to \infty} \big( \frac{1}{1^2} +
- \frac{1}{2^2} + \dots + \frac{1}{k^2} \big) \approx
- 6 \big( \frac{1}{1^2} + \frac{1}{2^2} + \dots + \frac{1}{n^2} \big)
-
-A simple python code for evaluating the truncated sum looks like this::
-
- #!/usr/bin/env python
- # encoding: utf-8
- # filename: calc_pi.py
-
- def recip_square(i):
- return 1./i**2
-
- def approx_pi(n=10000000):
- val = 0.
- for k in range(1,n+1):
- val += recip_square(k)
- return (6 * val)**.5
-
-On my box, this needs approximately 4 seconds to run the function with the
-default n. The higher we choose n, the better will be the approximation for
-:math:`\pi`. An experienced python programmer will already see plenty of
-places to optimize this code. But remember the golden rule of optimization:
-Never optimize without having profiled. Let me repeat this: **Never** optimize
-without having profiled your code. Your thoughts about which part of your
-code takes too much time are wrong. At least, mine are always wrong. So let's
-write a short script to profile our code::
-
- #!/usr/bin/env python
- # encoding: utf-8
- # filename: profile.py
-
- import pstats, cProfile
-
- import calc_pi
-
- cProfile.runctx("calc_pi.approx_pi()", globals(), locals(), "Profile.prof")
-
- s = pstats.Stats("Profile.prof")
- s.strip_dirs().sort_stats("time").print_stats()
-
-Running this on my box gives the following output::
-
- TODO: how to display this not as code but verbatimly?
-
- Sat Nov 7 17:40:54 2009 Profile.prof
-
- 10000004 function calls in 6.211 CPU seconds
-
- Ordered by: internal time
-
- ncalls tottime percall cumtime percall filename:lineno(function)
- 1 3.243 3.243 6.211 6.211 calc_pi.py:7(approx_pi)
- 10000000 2.526 0.000 2.526 0.000 calc_pi.py:4(recip_square)
- 1 0.442 0.442 0.442 0.442 {range}
- 1 0.000 0.000 6.211 6.211 <string>:1(<module>)
- 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
-
-This contains the information that the code runs in 6.2 CPU seconds. Note that
-the code got slower by 2 seconds because it ran inside the cProfile module. The
-table contains the real valuable information. You might want to check the
-python `profiling documentation <http://docs.python.org/library/profile.html>`_
-for the nitty gritty details. The most important columns here are totime (total
-time spend in this function **not** counting functions that were called by this
-function) and cumtime (total time spend in this function **also** counting the
-functions called by this function). Looking at the tottime column, we see that
-approximately half the time is spend in approx_pi and the other half is spend
-in recip_square. Also half a second is spend in range ... of course we should
-have used xrange for such a big iteration. And in fact, just changing range to
-xrange makes the code run in 5.8 seconds.
-
-We could optimize a lot in the pure python version, but since we are interested
-in Cython, let's move forward and bring this module to Cython. We would do this
-anyway at some time to get the loop run faster. Here is our first Cython version::
-
- # encoding: utf-8
- # cython: profile=True
- # filename: calc_pi.pyx
-
- def recip_square(int i):
- return 1./i**2
-
- def approx_pi(int n=10000000):
- cdef double val = 0.
- cdef int k
- for k in xrange(1,n+1):
- val += recip_square(k)
- return (6 * val)**.5
-
-Note the second line: We have to tell Cython that profiling should be enabled.
-This makes the Cython code slightly slower, but without this we would not get
-meaningful output from the cProfile module. The rest of the code is mostly
-unchanged, I only typed some variables which will likely speed things up a bit.
-
-We also need to modify our profiling script to import the Cython module directly.
-Here is the complete version adding the import of the pyximport module::
-
- #!/usr/bin/env python
- # encoding: utf-8
- # filename: profile.py
-
- import pstats, cProfile
-
- import pyximport
- pyximport.install()
-
- import calc_pi
-
- cProfile.runctx("calc_pi.approx_pi()", globals(), locals(), "Profile.prof")
-
- s = pstats.Stats("Profile.prof")
- s.strip_dirs().sort_stats("time").print_stats()
-
-We only added two lines, the rest stays completely the same. Alternatively, we could also
-manually compile our code into an extension; we wouldn't need to change the
-profile script then at all. The script now outputs the following::
-
- Sat Nov 7 18:02:33 2009 Profile.prof
-
- 10000004 function calls in 4.406 CPU seconds
-
- Ordered by: internal time
-
- ncalls tottime percall cumtime percall filename:lineno(function)
- 1 3.305 3.305 4.406 4.406 calc_pi.pyx:7(approx_pi)
- 10000000 1.101 0.000 1.101 0.000 calc_pi.pyx:4(recip_square)
- 1 0.000 0.000 4.406 4.406 {calc_pi.approx_pi}
- 1 0.000 0.000 4.406 4.406 <string>:1(<module>)
- 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
-
-We gained 1.8 seconds. Not too shabby. Comparing the output to the previous, we
-see that recip_square function got faster while the approx_pi function has not
-changed a lot. Let's concentrate on the approx_pi function a bit more. First
-note, that this function is not to be called from code outside of our module;
-so it would be wise to turn it into a cdef to reduce call overhead. We should
-also get rid of the power operator: it is turned into a pow(i,2) function call by
-Cython, but we could instead just write i*i which could be faster. The
-whole function is also a good candidate for inlining. Let's look at the
-necessary changes for these ideas::
-
- # encoding: utf-8
- # cython: profile=True
- # filename: calc_pi.pyx
-
- cdef inline double recip_square(int i):
- return 1./(i*i)
-
- def approx_pi(int n=10000000):
- cdef double val = 0.
- cdef int k
- for k in xrange(1,n+1):
- val += recip_square(k)
- return (6 * val)**.5
-
-Now running the profile script yields::
-
- Sat Nov 7 18:10:11 2009 Profile.prof
-
- 10000004 function calls in 2.622 CPU seconds
-
- Ordered by: internal time
-
- ncalls tottime percall cumtime percall filename:lineno(function)
- 1 1.782 1.782 2.622 2.622 calc_pi.pyx:7(approx_pi)
- 10000000 0.840 0.000 0.840 0.000 calc_pi.pyx:4(recip_square)
- 1 0.000 0.000 2.622 2.622 {calc_pi.approx_pi}
- 1 0.000 0.000 2.622 2.622 <string>:1(<module>)
- 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
-
-That bought us another 1.8 seconds. Not the dramatic change we could have
-expected. And why is recip_square still in this table; it is supposed to be
-inlined, isn't it? The reason for this is that Cython still generates profiling code
-even if the function call is eliminated. Let's tell it to not
-profile recip_square any more; we couldn't get the function to be much faster anyway::
-
- # encoding: utf-8
- # cython: profile=True
- # filename: calc_pi.pyx
-
- cimport cython
-
- @cython.profile(False)
- cdef inline double recip_square(int i):
- return 1./(i*i)
-
- def approx_pi(int n=10000000):
- cdef double val = 0.
- cdef int k
- for k in xrange(1,n+1):
- val += recip_square(k)
- return (6 * val)**.5
-
-Running this shows an interesting result::
-
- Sat Nov 7 18:15:02 2009 Profile.prof
-
- 4 function calls in 0.089 CPU seconds
-
- Ordered by: internal time
-
- ncalls tottime percall cumtime percall filename:lineno(function)
- 1 0.089 0.089 0.089 0.089 calc_pi.pyx:10(approx_pi)
- 1 0.000 0.000 0.089 0.089 {calc_pi.approx_pi}
- 1 0.000 0.000 0.089 0.089 <string>:1(<module>)
- 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
-
-First note the tremendous speed gain: this version only takes 1/50 of the time
-of our first Cython version. Also note that recip_square has vanished from the
-table like we wanted. But the most peculiar and import change is that
-approx_pi also got much faster. This is a problem with all profiling: calling a
-function in a profile run adds a certain overhead to the function call. This
-overhead is **not** added to the time spend in the called function, but to the
-time spend in the **calling** function. In this example, approx_pi didn't need 2.622
-seconds in the last run; but it called recip_square 10000000 times, each time taking a
-little to set up profiling for it. This adds up to the massive time loss of
-around 2.6 seconds. Having disable profiling for the often called function now
-reveals realistic timings for approx_pi; we could continue optimizing it now if
-needed.
-
-This concludes this profiling tutorial. There is still some room for
-improvement in this code. We could try to replace the power operator in
-approx_pi with a call to sqrt from the C stdlib; but this is not necessarily
-faster than calling pow(x,0.5).
-
-Even so, the result we achieved here is quite satisfactory: we came up with a
-solution that is much faster then our original python version while retaining
-functionality and readability.
-
-
projects / cython.git / commitdiff