Re: [Zope] ZopeProfiler (python profiler) - strange results

2005-07-20 Thread 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   percallfunction

...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

___
Zope maillist  -  Zope@zope.org
http://mail.zope.org/mailman/listinfo/zope
**   No cross posts or HTML encoding!  **
(Related lists - 
http://mail.zope.org/mailman/listinfo/zope-announce

http://mail.zope.org/mailman/listinfo/zope-dev )


[Zope] ZopeProfiler (python profiler) - strange results

2005-07-19 Thread 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   percallfunction

...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
___
Zope maillist  -  Zope@zope.org
http://mail.zope.org/mailman/listinfo/zope
**   No cross posts or HTML encoding!  **
(Related lists - 
http://mail.zope.org/mailman/listinfo/zope-announce

http://mail.zope.org/mailman/listinfo/zope-dev )