Profiling Code ============== .. toctree:: :maxdepth: 1 Indices and tables ------------------ * :ref:`genindex` * :ref:`modindex` * :ref:`search` Introduction ------------ Python ships with two modules to assist in understanding the execution of your code. The following code, ``profile_me.py``, will be used in the examples that follow: .. literalinclude:: profile_me.py :linenos: .. _section_heading-timeit: timeit ------ The :py:mod:`timeit` package provides functionality that allows you to benchmark the execution time of your code. One of the most popular functions to use from the package is: .. py:function:: repeat(stmt='pass', \ setup='pass', \ repeat=3, \ number=1000000, \ globals=None) Executes ``setup`` once followed by a timing test. A timing test is ``number`` executions of ``stmnt``. Repeat executing ``setup`` and the timing test ``repeat`` times (``setup`` is only executed at the start of each time test). Can supply a :py:class:`dict` object to specify the globals for the namespace that ``setup`` and ``stmt`` are executed in. All arguments are optional. The ``setup`` and ``stmt`` arguments can be specified in two ways: * As a string of Python statements to execute. Multiple statements in the string can be separated by ``;``. * As an object that is callable without arguments. The return value from the :py:mod:`~timeit.repeat` function is a list of the execution time in seconds for each timing test. For example, using the example code above and Python statements as strings: >>> from timeit import repeat >>> repeat(stmt='profile_me.main()', setup='import profile_me') [15.187742052017711, 15.206103866017656, 15.189024122984847] Again, but this time using a callable object without arguments: >>> from timeit import repeat >>> import profile_me >>> repeat(stmt=profile_me.main) [15.196357882989105, 15.172260118997656, 15.361751797958277] It is also possible to call the :py:mod:`timeit` code from the command line using the following format: .. code-block:: bash python -m timeit [-n N] [-r N] [-s S] [statement ...] Where: * -n specifies the number of time to execute statement * -r specifies the number of times to repeat the timing test * -s specifies the setup statement For example: .. code-block:: bash $ python3 -m timeit -n 1000000 -s 'import profile_me' 'profile_me.main()' 1000000 loops, best of 3: 15.1 usec per loop .. note:: Unlike the output in the Python console, the output on the command line is the time it takes to execute ``stmt`` a single time (be sure to notice the change in units). .. _section_heading-cProfile: cProfile -------- If you are interested in more detail than the single execution time value you get with :py:mod:`timeit`, you can use the :py:mod:`cProfile` package to generate an execution time profile for the function calls that occur in your program. .. note:: There is also the :py:mod:`profile` class, which is written in pure Python and may be easier to extend than :py:mod:`cProfile`. However, it adds a lot of overhead to the program being profiled and thus isn't generally recommended for use. The profiling operation can be started using the run method: .. py:method:: cProfile.run(command, filename=None, sort=-1) This method will execute ``command`` (which must be written in a string), profile it, and print the statistics to the terminal (or to disk if ``filename`` is given). Profiling the example code can be quickly done as shown below: .. code-block:: python :emphasize-lines: 4 import profile_me import cProfile cProfile.run('profile_me.main(1000, 1000)') 9 function calls in 0.142 seconds Ordered by: standard name ncalls tottime percall cumtime percall filename:lineno(function) 1 0.007 0.007 0.142 0.142 :1() 1 0.112 0.112 0.112 0.112 profile_me.py:14() 1 0.000 0.000 0.022 0.022 profile_me.py:17(sum_coords) 1 0.019 0.019 0.019 0.019 profile_me.py:24() 1 0.001 0.001 0.135 0.135 profile_me.py:28(main) 1 0.000 0.000 0.112 0.112 profile_me.py:6(get_even_coords) 1 0.000 0.000 0.142 0.142 {built-in method exec} 1 0.004 0.004 0.004 0.004 {built-in method sum} 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects} The columns have the following meaning: * ncalls - The number of calls. * tottime - The total time spent in the given function (and excluding time made in calls to sub-functions) * percall - The quotient of tottime divided by ncalls * cumtime - The cumulative time spent in this and all subfunctions (from invocation till exit). This figure is accurate even for recursive functions. * percall - The quotient of cumtime divided by primitive calls * filename:lineno(function) - Provides the respective data of each function You can also invoke the profiler from the command line if you want using the following syntax: .. code-block:: text python -m cProfile [-o output_file] [-s sort_order] myscript.py Where: * -o specifies the output file to dump the results to * -s specifies how to sort the output (accepts one of the :py:meth:`pstats.Stats.sort_stats` keys to sort on) The :py:class:`pstats.Stats` object can be used to sort the profile statistics returned by the :py:func:`cProfile.run` method. For example, to sort by total time: .. code-block:: python :emphasize-lines: 8 import profile_me import cProfile import pstats cProfile.run('profile_me.main(1000, 1000)', 'profile_results.txt') stats = pstats.Stats('profile_results.txt') stats.strip_dirs() stats.sort_stats('tottime') stats.print_stats() 9 function calls in 0.148 seconds Ordered by: internal time ncalls tottime percall cumtime percall filename:lineno(function) 1 0.116 0.116 0.116 0.116 profile_me.py:14() 1 0.019 0.019 0.019 0.019 profile_me.py:24() 1 0.008 0.008 0.148 0.148 :1() 1 0.004 0.004 0.004 0.004 {built-in method sum} 1 0.001 0.001 0.140 0.140 profile_me.py:28(main) 1 0.000 0.000 0.148 0.148 {built-in method exec} 1 0.000 0.000 0.023 0.023 profile_me.py:17(sum_coords) 1 0.000 0.000 0.116 0.116 profile_me.py:6(get_even_coords) 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects} Consult the :py:class:`pstats.Stats` documentation for further ways to sort.