The Profiler for measuring Zope calculation times
Hello, I have been using the Profiler from the Control Panel to try to figure ut the bottleneck parts of our site, but I don't really get results I can exploit. It goes too deep in Python for what I need at the moment. What I would need is some indication of the time used to calculate and render specific objects from the ZODB tree. For example the index_html rendering the contents of a specifc folder, or the left_bar_html if there is one called by this index_html. Is there a tool for doing that ? Regards, Kamon eXperts-MD
You can't measure certain methods without delving into Python. You might create an external method named "printTime" that just printed the start and end times to the console, e.g. import time def printTime(): print time.time() If that doesn't strike you, you can measure how long a certain URL takes to render by using the "big M" log and the requestprofiler (in Zope 2.4's utilities directory). But this won't let you see "inside" of the method that represents the URL (e.g. if the URL represents 'index_html', you won't be able to see how long the left_nav_bar takes).
Kamon Ayeva wrote:
Hello,
I have been using the Profiler from the Control Panel to try to figure ut the bottleneck parts of our site, but I don't really get results I can exploit. It goes too deep in Python for what I need at the moment. What I would need is some indication of the time used to calculate and render specific objects from the ZODB tree. For example the index_html rendering the contents of a specifc folder, or the left_bar_html if there is one called by this index_html. Is there a tool for doing that ?
Regards, Kamon eXperts-MD
-- Chris McDonough Zope Corporation http://www.zope.org http://www.zope.com """ Killing hundreds of birds with thousands of stones """
Thanks Chris for your quick answer, I am trying to elaborate on it. ----- Original Message ----- From: "Chris McDonough" <chrism@zope.com> To: "Kamon Ayeva" <kamon.ayeva@experts-md.com> Cc: <zope@zope.org> Sent: Tuesday, August 07, 2001 3:33 PM Subject: Re: [Zope] The Profiler for measuring Zope calculation times
You can't measure certain methods without delving into Python. You might create an external method named "printTime" that just printed the start and end times to the console, e.g.
import time def printTime(): print time.time()
Due to fact that I need to do the profiling on every Url, on a complex dynamic site, I can't do that.
If that doesn't strike you, you can measure how long a certain URL takes to render by using the "big M" log and the requestprofiler (in Zope 2.4's utilities directory). But this won't let you see "inside" of the method that represents the URL (e.g. if the URL represents 'index_html', you won't be able to see how long the left_nav_bar takes).
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. Thanks, Kamon
Kamon Ayeva wrote:
Hello,
I have been using the Profiler from the Control Panel to try to figure ut the bottleneck parts of our site, but I don't really get results I can exploit. It goes too deep in Python for what I need at the moment. What I would need is some indication of the time used to calculate and render specific objects from the ZODB tree. For example the index_html rendering the contents of a specifc folder, or the left_bar_html if there is one called by this index_html. Is there a tool for doing that ?
Regards, Kamon eXperts-MD
-- Chris McDonough Zope Corporation http://www.zope.org http://www.zope.com
""" Killing hundreds of birds with thousands of stones """
Kamon Ayeva wrote:
If that doesn't strike you, you can measure how long a certain URL takes to render by using the "big M" log and the requestprofiler (in Zope 2.4's utilities directory). But this won't let you see "inside" of the method that represents the URL (e.g. if the URL represents 'index_html', you won't be able to see how long the left_nav_bar takes).
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.
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 ? Thanks. Kamon eXperts-MD
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 """
Hi, Thanks to Chris McDonough for his input so far, but the Python profiler is not the right tool for the problem I currently try to solve on our site, which is evaluating the time spent in the DTML processing for pages. (When we have these numbers, we will be able to see if we need to work for tuning on the publishing side or our Python API side.) This is a relatively longer email trying to give more explanation on our need since we think this facility could be needed in Zope in general. Our version of Zope is Zope 2.2.2 (source release, python 1.5.2, linux2) Simplified structure of the site : + index_html (acquired all through the site) + FolderA - content_folder - Document - Document - Document + FolderB - content_folder - Document - Document Code in index_html: <dtml-var html_header> <dtml-var html_content> <dtml-var html_footer> To make it simple enough, html_header and html_footer respectively call standard_html_header and standard_html_footer methods. Code in html_content (also sits at the root): <dtml-if content_folder> <dtml-with content_folder> <dtml-in "objectValues (['DTML Document'])" sort=id skip_unauthorized> <H1> <dtml-var title> </H1> <dtml-var "_['sequence-item']"> </dtml-in> </dtml-with> </dtml-if> Note that in reality, the structure is a lot more complex, and that's why we need a tool for the profiling, but at Document Templates level, not Python level. What we would need is to get for each Url processed / rendered: 1/ the list of called DTML objects (Python scripts if any) 2/ the total time for each object 3/ the number of calls for each object So for example, if I hit the Url http://www.mysite.com/FolderA, I will get the following profiling report: method total time number of calls index_html 910 ms 1 html_header 250 ms 1 standard_html_header 50 ms 1 html_footer 100 ms 1 standard_html_footer 10 ms 1 html_content 500 ms 5 Do other people have the same need for getting to know the bottleneck parts of their DTML structure ? Thanks, Kamon eXperts-MD
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.
I suggest you hack the __call__ method of OFS/DTMLMethod.py to print out the time it takes, along with the physical path of the method that is running. You could do this by a hotfix-style runtime patch. Do the same for DTMLDocument too if you need it. -- Steve Alexander Software Engineer Cat-Box limited
participants (3)
-
Chris McDonough -
Kamon Ayeva -
Steve Alexander