Random notes from mg

a blog by Marius Gedminas

Marius is a Python hacker. He works for Programmers of Vilnius, a small Python/Zope 3 startup. He has a personal home page at http://gedmin.as. His email is marius@gedmin.as. He does not like spam, but is not afraid of it.

Thu, 30 Dec 2004

Profiling/tracing a single function

Sometimes you want to profile just a single function in your Python program. Here's a module that lets you do just that: profilehooks.py. Sample usage:

#!/usr/bin/python
from profilehooks import profile

class SampleClass:

    def silly_fibonacci_example(self, n):
        """Return the n-th Fibonacci number.

        This is a method rather rather than a function just to illustrate that
        you can use the 'profile' decorator on methods as well as global
        functions.

        Needless to say, this is a contrived example.
        """
        if n < 1:
            raise ValueError('n must be >= 1, got %s' % n)
        if n in (1, 2):
            return 1
        else:
            return (self.silly_fibonacci_example(n - 1) +
                    self.silly_fibonacci_example(n - 2))
    silly_fibonacci_example = profile(silly_fibonacci_example)


if __name__ == '__main__':
    fib = SampleClass().silly_fibonacci_example
    print fib(10)

(If you have Python 2.4, you can use @profile as a decorator just before the function definition instead of rebinding silly_fibonacci_example.)

Demonstration:

mg: ~$ python sample.py
55

*** PROFILER RESULTS ***
silly_fibonacci_example (sample.py:6)
function called 109 times

         325 function calls (5 primitive calls) in 0.004 CPU seconds

   Ordered by: internal time, call count

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    108/2    0.001    0.000    0.004    0.002 profilehooks.py:79(<lambda>)
    108/2    0.001    0.000    0.004    0.002 profilehooks.py:131(__call__)
    109/1    0.001    0.000    0.004    0.004 sample.py:6(silly_fibonacci_example)
        0    0.000             0.000          profile:0(profiler)

This decorator is useful when you do not want the profiler output to include time spent waiting for user input in interactive programs, or time spent waiting for requests in a network server.

In a similair vein you can produce code coverage reports for a function.

#!/usr/bin/python
import doctest
from profilehooks import coverage

def silly_factorial_example(n):
    """Return the factorial of n."""
    if n < 1:
        raise ValueError('n must be >= 1, got %s' % n)
    if n == 1:
        return 1
    else:
        return silly_factorial_example(n - 1) * n
silly_factorial_example = coverage(silly_factorial_example)


if __name__ == '__main__':
    print silly_factorial_example(1)

Demonstration:

mg: ~$ python sample2.py
1

*** COVERAGE RESULTS ***
silly_factorial_example (sample2.py:5)
function called 1 times

       def silly_factorial_example(n):
           """Return the factorial of n."""
    1:     if n < 1:
>>>>>>         raise ValueError('n must be >= 1, got %s' % n)
    1:     if n == 1:
    1:         return 1
           else:
>>>>>>         return silly_factorial_example(n - 1) * n

2 lines were not executed.

I found it useful to discover whether a given function or a method was adequately covered by unit tests.

Update: profilehooks is now a proper easy_install'able Python package.

posted at 00:16 | tags: | permanent link to this entry | 5 comments
Incidentally, I'm rather unhappy with Python profilers giving me the method name (__call__) but not the class name (did you see how many different __call__s there were?).  There's filename + line number (shown in a tooltip on hover), so you can figure that out yourself, but it's tedious.
posted by Marius Gedminas at Sat Aug 7 17:06:49 2010
I've pulled your changes upstream, the Routes recompiling is perhaps due to a setting where it re-scans the controllers every request during debug mode on Pylons apps. This can be turned off in the routing.py file.

Nice to see the improvements!
posted by Ben Bangert at Sat Aug 7 20:50:21 2010
Nice post
posted by Darius Damalakas at Mon Aug 9 12:35:27 2010
As you requested, I continue comments here, not on a Facebook (although why you post to FB then...). Anyway.

Yes, it is big step forward, since remembering traditional profiler. But still there must be a tons of work done to make it useful. I don't know why, but in 99% cases I don't need profiling for my applications just because I am like profiling them "on the fly" in my head, so I can mostly always say where it lags and why (and Profiler usually confirms that). However, Profiler is very useful if you can attach it to a real application running and test it on a real load — here we often do miscalculations, forgetting Big O (or just taking shortcuts in most cases). :)

As of graph, it looks really sexy and nice (at first glance), however (at second glance) I see nearly a little value of it, precisely no more value as just to see a whole hierarchy of... well, that's the question of what — no classes are visible either. Maybe I don't know something, but "get 42.32ms" tells me no more than somewhere some object is trying to pull out some other object out of some sort of collection and did that after 42.32ms. How this is helpful for you, if all important info I am looking for is just totally missing? I find it kinda useless, especially on projects like Plone, where bazillion slow classes are loaded to the expensive DDR3 just show some "hello world"... But again, I never tried Dozer, just reading your post, so I might be wrong.

Honestly, lately (maybe a few years) I don't use Python much for appdev (unless it is Jython or various Unix infrastructure works), but first thing as appdev that I am truly missing in a Python world to profile various bigger than few classes things is something like this: https://visualvm.dev.java.net/profiler.html — go ahead, take a look at that just out of curiosity.

Hence my suggestion here to Dozer stuff would be to tell what actually class is called in a graph. But then I have no idea how to preserve it look nice. Maybe it is better not to have this great looking graph (yes, it is really great looking, no sarcasm here), but instead just repeat the same layout as VisualVM has? For example, like you have a full class name, where it is located, how much does it take and what thing it is calling. That would make way more sense, I recon.

Also, maybe things in the first and last screenshots on a table better be sorted by load time (that beige bar in the middle)?

Well, I dunno, just a little few yen in a whole post. :-)
posted by BM at Wed Aug 11 15:24:30 2010
Loving the profiler.  I found coloring graph edges by call count on a logarithmic scale helpful for large graphs at times.
posted by yvl at Fri Oct 21 14:06:26 2011

Name (required)


E-mail (will not be shown)


URL


Comment (some HTML allowed)