[Zope] Re: Using the profiler (Was: The Profiler for measuring Zope calculation times)

[Chris McDonough]

Kamon Ayeva wrote:
> 
> Chris McDonough <chrism@zope.com> on Tuesday, August 07, 2001 4:11 PM:
> Subject: Re: [Zope] The Profiler for measuring Zope calculation times
> 
> > Kamon Ayeva wrote:
> 
> > > That's actually what I need. On the rendering of every URL, I have some
> > > presentation DTML methods calling each other (including a recursive DTML
> > > call). So I would like to know the percentage of time spent by each of
> these
> > > methods within the global page rendering time.
> >
> > You need the profiler for that, sorry.
> >
> 
> Unfortunately I have not yet found the way to use/interpret its output.
> If I have the following entry from the output of the profiler (the only one
> that has a total time (totime) > 2.000)...
> 
> 14006/26        4.117        0.000        73.477        2.826  DT_InSV.py:
> 379 (__getitem__)
> 
> ... I tend to think that at some point there is a DTML method doing some
> dtml-in processing with sequence variables.
> Is it all I can say or can I get more information that I can analyze ? It
> seems I cannot tell which method is doing that processing, can I ?

There is documentation for the profiler at python.org, BTW
(http://www.python.org/doc/current/lib/profile.html).  The output you
get from Zope is the Python profiler output.

Well, the method that's taking up this time is the __getitem__ method of
a class in DT_InSV.py (at line 379).  I don't know which version of Zope
you're running, so I'm not sure what this is, but it's likely the
__getitem__ method of the sequence_variables class.

Whether this information is useful or not depends on the context.  It's
frequently somewhat difficult to associate the profiler output with the
actual method calls you're trying to time.  I'd be tempted to restate
your requirements, as the problem you state might take lots of your
time.

What if you were to say "I want to time the performance of these
methods, and if its result is under 500ms, I'm not going to worry about
it, however, if it's over 500ms, I am going to worry about it".  That
way you can prevent yourself from gathering stats on lots of methods
that are fine.  The methods that remain can be profiled individually. 
You can then take one case, and follow the profile data through the
code, getting an understanding of what it means.  Once you do it once,
you'll be able to do it much faster the second and following times.

I unfortunately can't even start to give "do this, then do this" profile
tracing docs in email, mostly because I don't understand all the output
myself, and I need to work through it every time I trace through a
profile.  I don't think there is anyone who really understands Zope
profile output enough to be able to give you adequate docs to trace it,
unfortunately, because Zope does lots of "execing" and "evaling" under
the hood to service DTML, Python Scripts, et. al. which really tends to
muddle profile output.

OTOH, something I just thought of:  you can use the "Zope debugger" (see
the Zope Developer's Guide) to time methods manually "by hand" (using
the time module).  If you have a small enough number of methods, this
could be the way to go.

If you have methods that depend on the REQUEST, you can use the
makerequest script in the Testing package.

- C

-- 
Chris McDonough                           Zope Corporation
http://www.zope.org                    http://www.zope.com

""" Killing hundreds of birds with thousands of stones """