[Zope] ZopeProfiler (python profiler) - strange results

[Maciej Wisniowski]

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