python profiling, hotspot and strange execution time

[Jeremy Jones]

cournape at gmail.com wrote:

>Hi there,
>
>   I have some scientific application written in python. There is a
>good deal of list processing, but also some "simple" computation such
>as basic linear algebra involved. I would like to speed things up
>implementing some of the functions in C. So I need profiling.
>
>   I first tried to use the default python profiler, but profiling my
>application multiplies the execution time by a factor between 10 and
>100 ! So I decided to give a try to hotspot.
>
OK - first of all, as someone else has asked, what platform are you 
running?  I'm assuming it's windows since you're referring to 
time.clock() and then later saying "wall clock".

Next, what are you hoping that the profiler will give you?  If you're 
expecting it to give you the big picture of your application's 
performance and give you "real runtime numbers", you may be 
disappointed.  It is a deterministic profiler and will give you CPU time 
spent in different areas of code rather than and overall "how long did 
this thing take to run?".

> I just followed the
>example of the python library reference, but I have some strange
>results concerning cpu time. My profiling script is something like the
>following:
>
>def run_foo():
>    print time.clock()
>
>    function_to_profile()
>
>    print time.clock()
>
>prof = hotshot.Profile("essai.prof")
>benchtime= prof.runcall(run_foo)
>prof.close()
>stats = hotshot.stats.load("essai.prof")
>stats.strip_dirs()
>stats.sort_stats('time', 'calls')
>stats.print_stats(20)
>  
>

Well, let's just add more confusion to the pot, shall we?  Look at this 
example (a slight hack from yours)::

import time
import hotshot
import hotshot.stats


def run_foo():
    print time.clock()
    print time.time()

    time.sleep(5)

    print time.clock()
    print time.time()

prof = hotshot.Profile("essai.prof")
benchtime= prof.runcall(run_foo)
prof.close()
stats = hotshot.stats.load("essai.prof")
stats.strip_dirs()
stats.sort_stats('time', 'calls')
stats.print_stats(20)

and the output::

0.24
1126011669.55
0.24
1126011674.55
         1 function calls in 0.000 CPU seconds

   Ordered by: internal time, call count

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 tmphQNKbq.py:6(run_foo)
        0    0.000             0.000          profile:0(profiler)



I inserted a time.time() call since I'm on Linux and time.clock() 
returns a process's CPU time and wanted to show the "wall clock time" as 
it were.  So, the stats show 0 time taken, whereas time.time() shows 5 
seconds.  It's because the time.sleep() took a negligable amount of CPU 
time which is what the profiler looks at.

>The goal is to profile the function function_to_profile(). Running this
>script gives me a CPU executime time of around 2 seconds, whereas the
>difference between the two clock calls is around 10 seconds !
>
I would attribute the wall clock and profile time difference to the 
overhead of hotshot.  While hotshot is miles better than the "regular" 
profiler, it can still take a little time to profile code.

> And I
>don't run any other cpu consuming tasks at the same time, so this
>cannot come from other running processes. Is there something perticular
>about hotspot timing I should know ? I am not sure how I can get more
>accurate results with hotspot.
>
>I would appreciate any help, 
>
>Thanks
>
>  
>
HTH,


JMJ