..
   Copyright 2009-2017 Ram Rachum. This work is licensed under a Creative
   Commons Attribution-ShareAlike 3.0 Unported License, with attribution to
   "Ram Rachum at ram.rachum.com" including link. The license may be obtained
   at http://creativecommons.org/licenses/by-sa/3.0/

.. _topics-cute-profile:

:mod:`cute_profile`
===================

The :mod:`cute_profile` module allows you to profile your code (i.e. find out
which parts make it slow) by giving a nicer interface to the :mod:`cProfile`
library from Python's standard library.


What is "profiling"?
--------------------

(Programmers experienced with profilers may skip this section.)

To "profile" a piece of code means to run it while checking how long it takes,
and how long each function call inside the code takes. When you use a
"profiler" to profile your program, you get a table of (a) all the functions
calls that were made by the program, (b) how many times each function was
called and (c) how long the function calls took.

A profiler is an indispensable programming tool, because it allows the
programmer to understand which parts of his code take the longest. Usually,
when using a profiler, you discover that only a few small parts of his code
take most of the runtime of your program. And quite often, it's not the parts
of code that you *thought* were the slow ones.

Once you realize which parts of the program cause slowness, you can focus your
efforts on those problematic parts only, optimizing them or possibly
redesigning the way they work so they're not slow anymore. Then the whole
program becomes faster.

Profiling Python code with :mod:`cute_profile`
----------------------------------------------

Python supplies a module called :mod:`cProfile` in its standard library.
:mod:`cProfile` is a good profiler, but its interface can be inconvenient to
work with. The :mod:`cute_profile` module has a more flexible interface, and it
uses :mod:`cProfile` under the hood to do the actual profiling.

Let's profile an example program. Our example would be a function called
``get_perfects``, which finds `perfect numbers`_:

   >>> def get_divisors(x):
   ...     '''Get all the integer divisors of `x`.'''
   ...     return [i for i in xrange(1, x) if (x % i == 0)]
   ... 
   >>> def is_perfect(x):
   ...     '''Is the number `x` perfect?'''
   ...     return sum(get_divisors(x)) == x
   ... 
   >>> def get_perfects(top):
   ...     '''Get all the perfect numbers up to the number `top`.'''
   ...     return [i for i in xrange(1, top) if is_perfect(i)]      
   >>> print(get_perfects(20000))
   
The result is ``[6, 28, 496, 8128]``. However, this function takes a few
seconds to run. That's fairly long. Let's use :mod:`cute_profile` to find out
*why* this function is taking so long. We'll add the
:func:`cute_profile.profile_ready` decorator around ``get_perfects``:

   >>> from python_toolbox import cute_profile        
   >>> @cute_profile.profile_ready()
   ... def get_perfects(top):
   ...     '''Get all the perfect numbers up to the number `top`.'''
   ...     return [i for i in xrange(1, top) if is_perfect(i)]      


Now before we run ``get_perfects``, we set it to profile:

   >>> get_perfects.profiling_on = True

And now we run it:

   >>> print(get_perfects(20000))
   
We still get the same result, but now a profiling table gets printed::

            60000 function calls in 7.997 seconds
   
      Ordered by: cumulative time
   
      ncalls  tottime  percall  cumtime  percall filename:lineno(function)
           1    0.000    0.000    7.997    7.997 <string>:1(<module>)
           1    0.020    0.020    7.997    7.997 <pyshell#1>:2(get_perfects)
       19999    0.058    0.000    7.977    0.000 <pyshell#0>:5(is_perfect)
       19999    7.898    0.000    7.898    0.000 <pyshell#0>:1(get_divisors)
       19999    0.021    0.000    0.021    0.000 {sum}
           1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}        
        

This table shows how long each function took. If you want to understand
*exactly* what each number says in this table, see :func:`cProfile.run`.

The ``tottime`` column says how much time was spent inside this function,
across all calls, and without counting the time that was spent in
sub-functions. See how the ``get_divisors`` function in our example has a very
high ``tottime`` of 7.898 seconds, which is about 100% of the entire run time.
This means that ``get_divisors`` is what's causing our program to run slow, and
if we'll want to optimize the program, we should try to come up with a smarter
way of finding all of a number's divisors than going one-by-one over all
numbers.

:func:`profile_ready <cute_profile.profile_ready>` has a bunch of other options. In brief:

- The ``condition`` argument is something like a "breakpoint condition" in
  an IDE: It can be a function, usually a lambda, that takes the decorated
  function and any arguments and returns whether or not to profile it this time.
 
- ``off_after`` means whether you want the function to stop being profiled
  after being profiled one time. Default is :data:`True`.

- ``sort`` is an integer saying by which column the final results table
  should be sorted.


.. _perfect numbers: http://en.wikipedia.org/wiki/Perfect_number