# Presentation: 423193

## Python Profiling Tools

- DSD Department Meeting : October 1, 2004

- Subtitled: Why is my code so @#$% slow?

- Monte M. Goode

## Optimization Chores

- DSD Department Meeting : October 1, 2004

- When writing long-running application code to be deployed in a production environment, optimization will eventually become necessary.  Python is no exception.

- Tracking down memory leaks.
- Determining points where inlining code might be appropriate.
- Identifying inefficient libraries for potential replacement.
- Finding places where the authoring programmer simply did something dumb (only applicable to code authored outside of DSD).

## Python Standard Library Tools

- DSD Department Meeting : October 1, 2004

- Even though interpreted languages lack the pitfalls of explicit memory allocation, they still can leak memory and can certainly have algorithmic bottlenecks.
- The Python Standard Library provides a pair of tools to help the developer address this:

-  The sibling modules **profile** and **pstats**: full-featured code profiling tools.
-  The **gc** module: a more modestly-featured garbage collection analyzer.

## Profile.py and Pstats.py

- DSD Department Meeting : October 1, 2004

- Profile.py: just the profiler itself.  Merely generates the report file and offers no additional functionality.  This keeps any 'drag' that the profiler itself imposes on your running code to a minimum.  Could easily be invoked by a command-line flag.
-   if __name__ == ‘__main__’:
-     if getopt[‘generateProfile’] == True:
-       import profile
-       profile.run(‘main()’, ‘myProgramProf’)
-     else:
-       main()
- Pstats.py: slices and dices the report generated by profile.py.  Offers both a programmatic interface for the generation of scripted reports, and an interactive interface based on the **cmd** module.  I tend to use the interactive interface.

## What can pstats tell you?

- DSD Department Meeting : October 1, 2004

- A two step process:

- Sorting: criteria include both total and cumulative time (based in CPU seconds), method call count, method name, module name and others.  I employ the two time counts the most followed by method calls.
- Printing/restricting: after data is sorted, the displayed output may be further restricted numerically (ie: **n** number of lines), with regular expressions, and by interchangeable combinations of both.
- No matter how the data are sorted and restricted, the output includes call count, total and cumulative time (plus a per-call quotient for each), filename, line number and function name.

## Example Pstats Output

- DSD Department Meeting : October 1, 2004

-          141935 function calls (138569 primitive calls) in 2.640 CPU seconds
-    Ordered by: internal time
-    List reduced from 295 to 10 due to restriction <10>
-           ncalls  tottime  percall  cumtime  percall filename:lineno(function)
-   1019/102    0.170    0.000    0.450    0.004 compat.py:34(_do_element)
-            102    0.150    0.001    0.150    0.001 cDomlette.py:18(nonvalParse)
-        14652    0.120    0.000    0.120    0.000 string.py:362(replace)
-          2548    0.110    0.000    0.110    0.000 dom.py:731(findDefaultNS)
-          2036    0.090    0.000    0.200    0.000 c14n.py:227(_do_attr)
-          3392    0.080    0.000    0.120    0.000 TC.py:137(__init__)
-            609    0.080    0.000    0.520    0.001 TC.py:399(serialize)
-            309    0.060    0.000    0.230    0.001 Addressing_types.py:83(__init__)
-     208/104    0.060    0.000    0.210    0.002 TCcompound.py:136(parse)
- 2853/1529    0.060    0.000    0.170    0.000 dom.py:110(_getPrefix)

- This output has been sorted by internal time, restricted to the top 10 entries, and have had the full file pathnames stripped.

## Where did that come from?

- DSD Department Meeting : October 1, 2004

- Also of note is the paired callers/callees printing and restriction utility.  As the names imply, it allows the user to pinpoint where a function is being called, or what functions it is calling.  Employs same numeric/regex restriction patterns.

-    Ordered by: internal time
-    List reduced from 295 to 1 due to restriction <'TCcompound.py:136'>
-                    Function                  was called by...
-    TCcompound.py:136(parse)   TCcompound.py:136(parse)(104)    0.210
-                                                    parse.py:309(Parse)(2)    0.020
-                                                    parse.py:332(ParseHeaderElements)(102)    0.420

- This comes in handy when you are on search and destroy missions, or are looking to inline code.

## Anecdotes

- DSD Department Meeting : October 1, 2004

- Out damned spot!...the hunt for minidom: we thought that we had exercised a slow pure python DOM library from our code base, pstats showed that was not the case, and made pinpointing the offending method calls a matter of seconds, rather than minutes or hours.
- It costs how much?...greedy standard libraries: when drag racing our Globus 4 alpha code against the competition, I discovered that a single instance of the Python std lib logging object was placing significant drag on our code – to the tune of a couple CPU seconds.
- I knew C was faster....but that much faster?: the numbers pretty much speak for themselves:

- with PyXML:
- 195029 function calls (191674 primitive calls) in 2.500 CPU seconds
- with cDomlette:
- 6870 function calls (6547 primitive calls) in 0.110 CPU seconds

## Current Profiler Weaknesses

- DSD Department Meeting : October 1, 2004

- Strengths aside, there are currently a few known points of deficiency with the Python profiler:

- No threads.  (Ouch!)  As far as the profiler is concerned, code executed in threads use no CPU time.
- Does not profile C extension code.  It does however “charge” the calling function with the time spent in the extension code, so one can still get a good idea.  This will be fixed in Python 2.4.

## My program keeps growing!

- DSD Department Meeting : October 1, 2004

- When employing reference count-style garbage collection, opportunities to leak memory are very much there.  Consider the following code:

- class Foo:
-    def __init__(self, p):
-       self.parent = p
-       self.interestingData = 'sublime'
- class Bar:
-    def __init__(self):
-       self.data = Foo(self)
- leakyObject = Bar()
- del leakyObject

- One of Bar's data members holds a reference to it.  Bar's reference count will never drop to zero and it will not be garbage collected.

## The gc module

- DSD Department Meeting : October 1, 2004

- The gc module provides hooks into the Python garbage collector to give you at least a fighting chance of tracking leaks down.  Example usage:

- #!/bin/env python
- from leakyLib import Bar
- import gc
- gc.enable()
- gc.set_debug(gc.DEBUG_LEAK)
- bad = Bar()
- bad.stuff()
- del bad
- # force garbage collection
- gc.collect()
- if len(gc.garbage):
-   print 'busted'
-   for leak in gc.garbage:
-     print leak

- Any objects or data structures in the gc.garbage list after collect() has been called (and after said objects ought to have fallen out of scope) have not been garbage collected.  These are your culprits.

## Less Robust

- DSD Department Meeting : October 1, 2004

- While utilitarian, gc offers a lot less than the profiler does as far as pinpoint accuracy goes.

- Provides a pair of get_referrers/referents() methods but due to Python's internal reference handling, the output from these can be a little too noisy to be really useful.
- No reality-to-line-number mapping: it would be useful to see the line number where your tenacious reference resides.  As it is, it's mostly a starting point.

- But in the end, a list of objects that won't garbage collect is better than a sharp stick in the eye.  A starting point is better than nothing.

## Conclusions

- DSD Department Meeting : October 1, 2004

- The profiler/pstats combination is amazingly useful, and with a bit of practice, the interactive tool is easy to use.  The fact that the a profile could be generated with an optional command-line flag is icing on the cake.
- The gc module while useful, is a bit lacking in the feature department.  Rather than using it to debug a large existing code base, it would perhaps be better employed “as you go” thru the development cycle.  And it's worth noting that clever use of the **weakref** module will prevent circular references from happening in the first place.

## The End

- DSD Department Meeting : October 1, 2004

- Optional hands-on demo after meeting is over for anyone interested.
- Have a nice weekend.
- Fin.