Friday, May 6, 2011

Profiling in Python: Who called the function?

I'm profiling in Python using cProfile. I found a function that takes a lot of CPU time. How do I find out which function is calling this heavy function the most?

EDIT:

I'll settle for a workaround: Can I write a Python line inside that heavy function that will print the name of the function that called it?

From stackoverflow
  • That may not answer your question directly, but will definitely help. If use the profiler with option --sort cumulative it will sort the functions by cumulative time. Which is helpful to detect not only heavy functions but the functions that call them.

    python -m cProfile --sort cumulative myScript.py
    

    There is a workaround to get the caller function:

    import inspect
    print inspect.getframeinfo(inspect.currentframe().f_back)[2]
    

    You can add as many f_back as you want in case you want the caller caller etc If you want to calculate frequent calls you can do this:

    record = {}
    
    caller = inspect.getframeinfo(inspect.currentframe().f_back)[2]
    record[caller] = record.get(caller, 0) + 1
    

    Then print them by order of frequency:

    print sort(key=lambda a: a[1], record.items())
    
  • I have not used cProfile myself, but most profilers give you a call hierarchy.
    Googling I found this slides about cProfile. Maybe that helps. Page 6 looks like cProfile does provide a hierarchy.

  • inspect.stack() will give you the current caller stack.

  • I almost always view the output of the cProfile module using Gprof2dot, basically it converts the output into a graphvis graph (a .dot file), for example:

    example gprof2dot output

    It makes it very easy to determine which function is slowest, and which function[s] called it.

    Usage is:

    python -m cProfile -o output.pstats path/to/your/script arg1 arg2
    gprof2dot.py -f pstats output.pstats | dot -Tpng -o output.png
    
    ChristopheD : Seems like a cool tool, will have to try this out ;-)
  • Sorry I'm not familiar with Python, but there's a general method that works, assuming you can manually interrupt execution at a random time.

    Just do so, and display the call stack. It will tell you, with high probability, what you want to know. If you want to be more certain, just do it several times.

    It works because the guilty caller has to be on the call stack for the fraction of time that's being wasted, which exposes it to your interrupts for that much of the time, whether it is spread over many short calls or a few lengthy ones.

    NOTE: This process is more like diagnosis than measurement. Suppose that bad call is wasting 90% of the time. Then each time you halt it, the probability is 90% that the bad call statement is right there on the call stack for you to see, and you will be able to see that it's bad. However, if you want to exactly measure the wastage, that's a different problem. For that, you will need a lot more samples, to see what % of them contain that call. Or alternatively, just fix the guilty call, clock the speedup, and that will tell you exactly what the wastage was.

  • You might want to take a look at pycallgraph.

0 comments:

Post a Comment

Note: Only a member of this blog may post a comment.