profiling.rst 2.25 KB
Newer Older
dulak's avatar
dulak committed
1 2 3 4 5 6
.. _profiling:

=========
Profiling
=========

dulak's avatar
dulak committed
7 8 9
profile
=======

10 11
Python has a ``profile`` module to help you find the places in the
code where the time is spent.
dulak's avatar
dulak committed
12

13 14
Let's say you have a script ``script.py`` that you want to run through the
profiler.  This is what you do:
dulak's avatar
dulak committed
15 16

>>> import profile
17
>>> profile.run('import script', 'prof')
dulak's avatar
dulak committed
18

19 20 21
This will run your script and generate a profile in the file ``prof``.
You can also generate the profile by inserting a line like this in
your script::
dulak's avatar
dulak committed
22 23 24

  ...
  import profile
jensj's avatar
jensj committed
25
  profile.run('atoms.get_potential_energy()', 'prof')
dulak's avatar
dulak committed
26 27 28 29 30 31
  ...

To analyse the results, you do this::

 >>> import pstats
 >>> pstats.Stats('prof').strip_dirs().sort_stats('time').print_stats(20)
dulak's avatar
dulak committed
32 33 34 35 36 37 38 39 40 41 42 43 44 45 46
 Tue Oct 14 19:08:54 2008    prof

         1093215 function calls (1091618 primitive calls) in 37.430 CPU seconds

   Ordered by: internal time
   List reduced from 1318 to 20 due to restriction <20>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    37074   10.310    0.000   10.310    0.000 :0(calculate_spinpaired)
     1659    4.780    0.003    4.780    0.003 :0(relax)
   167331    3.990    0.000    3.990    0.000 :0(dot)
     7559    3.440    0.000    3.440    0.000 :0(apply)
      370    2.730    0.007   17.090    0.046 xc_correction.py:130(calculate_energy_and_derivatives)
    37000    0.780    0.000    9.650    0.000 xc_functional.py:657(get_energy_and_potential_spinpaired)
    37074    0.720    0.000   12.990    0.000 xc_functional.py:346(calculate_spinpaired)
dulak's avatar
dulak committed
47 48 49
      ...
      ...

50 51
The list shows the 20 functions where the most time is spent.  Check
the pstats_ documentation if you want to do more fancy things.
dulak's avatar
dulak committed
52

53
.. _pstats: http://docs.python.org/library/profile.html
dulak's avatar
dulak committed
54 55 56 57 58 59 60 61


.. tip::

   Since the ``profile`` module does not time calls to C-code, it
   is a good idea to run the code in debug mode - this will wrap
   calls to C-code in Python functions::

62
     $ python3 script.py --debug
dulak's avatar
dulak committed
63

64 65 66 67 68 69 70 71 72 73 74 75
.. tip::

   There is also a quick and simple way to profile a script::

     $ pyhton script.py --profile=prof

   This will produce a file called ``prof.0000`` where ``0000`` is the
   rank number (if your run the script in parallel, there will be one
   file per rank).

   Use::

76
     $ python3 script.py --profile=-
77 78

   to write the report directly to standard output.