Wanted to share this with both lists because I think it's
very relevant
to Bricolage performance...
I ran some analysis today on SQL queries generated by
story->list() with
the 'story.category' parameter present and found the
resulting queries
to be orders of magnitude slower than any other queries that
showed up
during a burn process.
I ran vacuum and analyze on my postgres database and added a
few more
indexes as well, but only managed to eek out a 20%
improvement. I
traced the problem down to some nested select statements
that were
causing loops in PostGres exceeding 300,000+ iterations.
As a workaround, it seems to be much more efficient to
simply grab the
list of story categories and then call story->list() with
the
'category_id' parameter instead. You could build a hash
indexed with
the story id to eliminate any duplicates that are returned
via this
method.
This probably isn't much of an issue if you're only burning
one story at
a time, but if you have many stories that you're burning at
once (e.g.
blaze_another, preview_another, etc), or using SOAP to
regenerate the
site, etc. it can really add up.
As far as a permanent fix, it might make sense to either
optimize the
SQL generated by this parameter or change the code that
handles the
'story.category' parameter to loop through the list like I'm
doing in my
templates.
Here are some standouts from a PostGres trace that highlight
the
differences. I would also expect the performance further
decline as I
add more data -- I have a very small number of objects in
the system
right now.
--> LOG: duration: 2005.660 ms statement: EXECUTE
<unnamed> [PREPARE:
LOG: duration: 0.210 ms statement: EXECUTE <unnamed>
[PREPARE:
LOG: duration: 0.236 ms statement: EXECUTE <unnamed>
[PREPARE:
LOG: duration: 0.251 ms statement: EXECUTE <unnamed>
[PREPARE:
LOG: duration: 0.113 ms statement: EXECUTE <unnamed>
[PREPARE:
LOG: duration: 0.234 ms statement: EXECUTE <unnamed>
[PREPARE:
LOG: duration: 0.114 ms statement: EXECUTE <unnamed>
[PREPARE:
LOG: duration: 0.224 ms statement: EXECUTE <unnamed>
[PREPARE:
LOG: duration: 0.270 ms statement: EXECUTE <unnamed>
[PREPARE:
LOG: duration: 0.267 ms statement: EXECUTE <unnamed>
[PREPARE:
LOG: duration: 0.183 ms statement: EXECUTE <unnamed>
[PREPARE:
LOG: duration: 0.255 ms statement: EXECUTE <unnamed>
[PREPARE:
LOG: duration: 0.149 ms statement: EXECUTE <unnamed>
[PREPARE:
LOG: duration: 0.220 ms statement: EXECUTE <unnamed>
[PREPARE:
LOG: duration: 1.683 ms statement: EXECUTE <unnamed>
[PREPARE:
LOG: duration: 0.248 ms statement: EXECUTE <unnamed>
[PREPARE:
LOG: duration: 0.102 ms statement: EXECUTE <unnamed>
[PREPARE:
SELECT category__id, main FROM story__category WHERE
story_instance__id=$1 ]
LOG: duration: 0.769 ms statement: EXECUTE <unnamed>
[PREPARE:
LOG: duration: 0.104 ms statement: EXECUTE <unnamed>
[PREPARE:
LOG: duration: 0.267 ms statement: EXECUTE <unnamed>
[PREPARE:
--> LOG: duration: 1900.849 ms statement: EXECUTE
<unnamed> [PREPARE:
|