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