An IronPython Profiler

I was recently working on improving the performance of a Python-based application and thought it would be useful to profile my code.  My intuition was telling me that the problem was in a certain area of the code, but I wanted hard numbers to back up this intuition before I went to the trouble of doing a rewrite.  Unfortunately, neither the CLR Profiler nor the profiling support in Visual Studio are very effective when used with IronPython, as they weren’t really created for environments where code is dynamically compiled at runtime.

But Tomáš had written a profiler for IronRuby nearly half a year ago, so I thought I’d port this to IronPython, where it’s now experimentally available in IronPython 2.6 Alpha 1.

The way Tomáš’ profiler works is pretty straightforward.  At the start of every method we compile, a snapshot is taken of the current time.  Another is taken at the end of the method and the difference is stored for later retrieval.  The only tricky thing about it is trying to update the statistics in a manner that’s both thread-safe and has minimal effect on performance.

I’ve modified it a bit from the original, though, and added some fun features.  In particular, it now tracks the number of calls made to each method and also keeps separate counters for the amount of time spent exclusively inside the method versus the duration spent inclusively in both this method and in any methods it calls.

Additionally, I’ve added counters to track calls made from Python code into statically-compiled .NET code.

Here’s a sample program profile.py that demonstrates the statistics we’re gathering by printing them on exit.

 import atexit
import clr
from System.Threading import Thread

def delay(seconds):
    Thread.CurrentThread.Join(1000 * seconds)

def print_profile():
    for p in clr.GetProfilerData():
        print '%s\t%d\t%d\t%d' % (p.Name, p.InclusiveTime, p.ExclusiveTime, p.Calls)

atexit.register(print_profile)
delay(1)

The profiler isn’t enabled by default, as it does have a small impact on performance.  You need to opt into it by running IronPython with the flag “-X:EnableProfiler”.  If you use this flag with the above code, you’ll get the following output:

These records are returned in the order that they were compiled, not the order that they were first called – except that methods which were never called are omitted entirely.

A record with the name “module site” means the top-level import of the site module.

Other records that start with the name “module” refer to Python code.

Records that start with “type” refer to .NET code that is called directly from IronPython.

Times are recorded in “Ticks”, which are increments of 100ns.  That means that the 10077140 ticks spent in the Thread.Join method are actually 1.007714 second.

Here’s what this profiler doesn’t do a good job of recording: the time required to parse Python, compile it into expression trees, generate the IL and JIT the IL.  Some of this is accounted for in the time it takes to import an external module, but not in a way that provides visibility to the constituent parts.

We’d love to get your feedback on this experimental addition to IronPython.  Happy profiling!

Comments

• Anonymous
  March 30, 2009
  I almost forgot the punchline: it turned out that I was totally wrong about the bottleneck in my code.  Score -1 for faith-based optimization, +1 for data-based tuning.
• Anonymous
  April 12, 2009
  The only feedback I’ve gotten so far about the IronPython Profiler is that it would be nice not to have