Profiling made easy

Recently I had to profile some pages on a Plone 2.5 (zope 2.9). I collected some datas on interesting pages with the help of the well-known ZopeProfiler 1.7.2 but I had to patch it to avoid an error:

--- ZopeProfiler.py~ 2007-06-26 10:43:25.000000000 +0200
+++ ZopeProfiler.py 2008-12-22 18:02:26.000000000 +0100
@@ -393,10 +393,10 @@
# Five broke 'getPhysicalPath' for its view classes -- work around
try: p= gP()
except:
-      _log.error("calling 'getPhysicalPath' failed for %r", s,
-                 exc_info=sys.exc_info()
-                 )
-      return
+        #         _log.error("calling 'getPhysicalPath' failed for %r", s,
+        #                    exc_info=sys.exc_info()
+        #         )
+        return ('?', _Empty, fn)
if type(p) is StringType: fi= p
else: fi= '/'.join(p)
return (fi,_Empty,fn)

A few years ago we had no other option than digging in the raw stats as they come from Stats.sort_stats().print_stats(). Since then there is a new tool: Gprof2dot. The author also made something more than handy: xdot.py.

Now just add a little bash function:

$ function build_dot() { ./gprof2dot.py -f pstats -o $(basename $1 .pstats).dot $1; }

Then my workflow for profiling some pages could be faster and easier:

1. Profile a page, and save "some_page.pstats"
2. run "build_dot some_page.pstats"
3. run "./xdot.py some_page.dot"
4. visit the graph
   

Here is the first overview:

The mouse wheel allows to zoom in/out, holding left-click and moving the mouse will move the graph. It's quite easy to quickly find some hotspots, sometimes they will appear very obviously:

I can read: 69% of total time spent in schema copy. In this particular case I know there is just one object with a "Schema" method, so probably it would be a good idea to review the code here to reduce the number of schema copies, or thinking about adding some cache decorator if it's possible (like plone.memoize). The graph does not tell what to do, though ;-)

Another interesting hotspot (in plone 2.5): for some pages up to 15% of the time in spent in... getAllowedTypes (just 1 call - nearly 11% in pythonproducts.py __bobo_traverse__).