python profiling, hotspot and strange execution time
zanesdad at bellsouth.net
Thu Sep 8 13:11:07 CEST 2005
cournape at gmail.com wrote:
>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
I think from below you said you were more clear on this. Cool.
>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?
More information about the Python-list