How slow should dtml-var be? (was: RE: [Zope] Problems with *BIG*SQL queries)

[Matthew T. Kromer]

Phil, one thing I'd recommend is consider using an external
method to create your report; you might be pleasantly surprised.

This means, instead of

     <dtml-in QUERY>
          <dtml-var ...> (etc)
     </dtml-in>

You do a <dtml-var expr="myExMeth(REQUEST, QUERY)">

And your external method gets the REQUEST and QUERY objects to
do its thing, format the results, and return it as one big item.

It might *significantly* cut down on your time, since what's
killing you is <dtml-var> * 38300.

For the performance minded, it's informative to do things like
run ab against a blank dtml method, then one with one dtml-var,
then two, etc...  On a 1Ghz CPU, it seems like you can get at
least 180tps without any dtml-vars, then about 166 with 1, then
about 150 with 2, etc...

I think (I'm going by memory) that this translates to about 5.5
million 386 cycles for Zope to serve a page, and about an extra
500,000 cycles per dtml-var.  Your milage may vary, of course.

If I'm right, that would be about 19.1 billion cycles to render
your page of 38300 dtml-vars.  Thats about 19 sec on a 1GHz CPU
(or about 5.3 hours on an Apple ][), but you'd loose some time
to system overhead, and if you're if you're on a 200MHz machine,
you're talking about 19 * 5 or 100 sec.  Given that you're
reporting that the query itself takes 30 seconds, if you
subtract that from your 4 minutes, you get about 210 seconds
left, so I'm only wrong by a factor of two.  Which is pretty
good for my guesstimates (I normally consider "good" to be
within 4X on a guess.)

The moral of the story is dynamic is good, but let's be
reasonably dynamic :)  

It also suggests that there's an area where large SQL
processing/table generation should be moved out of python for
faster rendering.


"Mayers, Philip J" wrote:
> 
> As mentioned, I'm doing really big SQL queries which return a HTML report
> that's about 1Mb. The ZopeTime trick suggested by Alan helps a lot - the
> time spent really is on the Zope side, and happens even with the most
> minimal file - just a:
> 
> <dtml-var "ZopeTime()">
> <dtml-in QUERY>
> <dtml-var column1>,<dtml-var column2>,<dtml-var column3>,<dtml-var column4>
> </dtml-in>
> <dtml-var "ZopeTime()">
> 
> This takes about 4 minutes *on the server* - file return is quick. *Sigh*.
> This however:
> 
> <dtml-var "ZopeTime()">
> <dtml-in QUERY>
> </dtml-in>
> <dtml-var "ZopeTime()">
> 
> Takes about 30 seconds (which is reasonable):
> 
> HTTP/1.1 200 OK
> Date: Wed, 21 Mar 2001 14:02:07 GMT
> Server: Apache/1.3.14 (Unix)  (Red-Hat/Linux)
> X-Powered-By: Zope (www.zope.org), Python (www.python.org)
> Vary: Authorization
> Content-Length: 94
> Connection: close
> Content-Type: text/plain
> 
> 2001/03/21 14:02:07.2783 GMT
> 2001/03/21 14:02:46.6733 GMT
> 
> I can only assume it's the namespace lookup in <dtml-var variable> - in
> fact, my calculations (9575 rows, 4 <dtml-var>s per row) make that 6ms per
> dtml-var, which isn't unreasonable. I guess I really do just have too much
> data...
> 
> Using a PythonScript:
> 
> print context.ZopeTime()
> for result in container.QUERY():
>     print "%s,%s,%s,%s" % (r.column1,r.column2,r.column3,r.column4)
> print context.ZopeTime()
> return printed
> 
> ...doesn't seem to help
> 
> Regards,
> Phil