[Zope] ZopeProfiler (python profiler) - strange results

[Chris Withers]

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