ZopeProfiler (python profiler) - strange results
Hi! I've just run ZopeProfiler few times to check which functions are slowest in my site and during analysis of the results I've found something that confuses me a bit. When I'm showing results using "print_stats" and ordered by "time" I get times: calls tottime percall cumtime percall function ... total_x ... cumulative_x ... X:1026(__call__) for function X. This seemed good till I've used "print_callees" format which showed me that function X is calling function Y and Z and their execution times are: functions_time = Y_call_time + Z_call_time. As far as I understand it "tottime" is the time without subfunctions' call times and "cumtime" is with subfunctions' call times, so I supposed that: cumulative_x - functions_time = total_x but this is not true... in almost every case I've checked it is rather: total_x + functions_time > cumulative_x Why? I don't think these are concurrent threads... but what makes this difference? It's possibly something trivial but... ;) -- Maciej Wisniowski
You might get more help by asking this question on one of the python lists, I know the profiler output has confused the hell out of me on more than one occasion ;-) Chris Maciej Wisniowski wrote:
Hi!
I've just run ZopeProfiler few times to check which functions are slowest in my site and during analysis of the results I've found something that confuses me a bit.
When I'm showing results using "print_stats" and ordered by "time" I get times:
calls tottime percall cumtime percall function
... total_x ... cumulative_x ... X:1026(__call__)
for function X.
This seemed good till I've used "print_callees" format which showed me that function X is calling function Y and Z and their execution times are:
functions_time = Y_call_time + Z_call_time.
As far as I understand it "tottime" is the time without subfunctions' call times and "cumtime" is with subfunctions' call times, so I supposed that:
cumulative_x - functions_time = total_x
but this is not true... in almost every case I've checked it is rather:
total_x + functions_time > cumulative_x
Why? I don't think these are concurrent threads... but what makes this difference? It's possibly something trivial but... ;)
-- Simplistix - Content Management, Zope & Python Consulting - http://www.simplistix.co.uk
Maciej Wisniowski wrote at 2005-7-19 23:31 +0200:
... This seemed good till I've used "print_callees" format which showed me that function X is calling function Y and Z and their execution times are:
functions_time = Y_call_time + Z_call_time.
As far as I understand it "tottime" is the time without subfunctions' call times and "cumtime" is with subfunctions' call times, so I supposed that:
cumulative_x - functions_time = total_x
but this is not true... in almost every case I've checked it is rather:
total_x + functions_time > cumulative_x
Why?
The complete calling statistics is very complex. Therefore, the profiler does not record the complete information but only summary information. Especially, it only records the time spend in a given function (say "X") but not the different times when "X" is called in different contexts (e.g. by "A" and "B"). As a consequence, the timings given by the "callees" view are usually too large for the given context (they show the "X" is called by "A" but the time given for "X" is the total time spend during any call of "X" and not only any call from "A"). -- Dieter
participants (3)
-
Chris Withers -
Dieter Maurer -
Maciej Wisniowski