python profiling, hotspot and strange execution time

[Jeremy Jones]

cournape at gmail.com wrote:
<snip>

>I am not sure to understand the big difference between "time spent in
>different areas of code" and "how long did this thing take to run?".
>Looking at python doc for deterministic profiling, I understand the
>implementation difference, and the performance implications, but I
>don't see why deterministic profiling would not give me an overall
>picture ?
>  
>
I think from below you said you were more clear on this.  Cool.

<snip>

>Well, your example make actually more sense to me :) I understand the
>difference between CPU time and time spent in the python code (even if
>I was not clear in my previous post about it...). But this case does
>not apply to my code, as my code is never "idled", takes 100 % of the
>cpu, with no other CPU consuming task
>
>  
>
>>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.
>>    
>>
>
>Well, if hotshot reported a timing which is longer than the execution
>time without it, I would have considered that to be normal. Even in C,
>using gprof has a non negligeable overhead, most of the time.
>  
>
Actually, I'd expect the opposite, but not as extreme for your case.  I 
would expect it to *report* that a piece of code took less time to 
execute than I *observed* it taking.  Reasons in the snipped area 
above.  Unless you're calling a C extension, in which case, IIRC, it's 
supposed to report the actual execution time of the C call (and I guess 
plus any overhead that hotshot may cause it to incur) in which case you 
would be IMO 100% correct.  I hope you're not calling a C extension, or 
my head's gonna explode.

>What I don't understand is why hotshot reports that do_foo is executed
>in 2 seconds whereas it effectively takes more than 10 seconds ? Is it
>because I don't understand what deterministic profiling is about ?
>  
>
The profiler is supposed to be smart about how it tracks time spent in 
execution so it doesn't get readings that are tainted by other processes 
running or other stuff.  I could easily see a 2->10 second disparity if 
your process were idling somehow.  Now, if you're doing a lot of IO, I 
wonder if the profiler isn't taking into consideration any blocking 
calls that may max out the CPU in IOWAIT...  Are you doing a lot of IO?

>David
>
>  
>
JMJ