Mailing List Archive

On 20-Apr-09, at 10:54 AM, Bret Dawson wrote:

> Greg had a look at why this was, and concluded that it was because
> Bricolage was taking a long time to look through the story's event
> log,
> so that it could be returned to the location (desk, shelf, etc.) where
> it was before the checkout happened.

I tracked it down to Bric::App::Callback::Profile::Story->cancel. The
Bric::Util::Event->list() call is what takes a really long time. As
Bret mentioned, if where the story came from (desk, shelf) could be
stored somewhere on checkout, it would be easy to put it back when the
checkout is cancelled. Of course I have no idea where this should/can
be stored.

I think the table is indexed properly and it's just a lot of records
in the event table slowing things down. Here's the Event->list() query
plan anyway, just in case.

-Greg


=> EXPLAIN ANALYZE SELECT e.id, t.id, e.usr__id, e.obj_id,
e.timestamp, t.key_name, t.name, t.description, c.pkg_name, CASE WHEN
e.id IN (SELECT event__id FROM alert) THEN 1 ELSE 0 END, ta.name,
ea.value FROM event e LEFT JOIN event_attr ea ON e.id = ea.event__id
LEFT JOIN event_type_attr ta ON ea.event_type_attr__id = ta.id, class
c, event_type t WHERE e.event_type__id = t.id AND t.class__id = c.id
AND e.obj_id = 1039 AND LOWER(c.pkg_name) LIKE
LOWER('bric::biz::asset::business::story') ORDER BY e.timestamp DESC,
e.id DESC;

Sort (cost=279417.82..279422.83 rows=2005 width=148) (actual
time=599666.940..599756.941 rows=128365 loops=1)
Sort Key: e."timestamp", e.id
-> Hash Join (cost=121943.89..279307.85 rows=2005 width=148)
(actual time=266073.080..592386.857 rows=128365 loops=1)
Hash Cond: ("outer".event_type__id = "inner".id)
-> Hash Left Join (cost=121924.59..278470.74 rows=158417
width=44) (actual time=265973.080..592006.853 rows=128405 loops=1)
Hash Cond: ("outer".event_type_attr__id = "inner".id)
-> Merge Right Join (cost=121923.10..276093.00
rows=158417 width=38) (actual time=265973.080..591936.852 rows=128405
loops=1)
Merge Cond: ("outer".event__id = "inner".id)
-> Index Scan using fkx_event__event_attr on
event_attr ea (cost=0.00..136599.74 rows=6469694 width=18) (actual
time=20.000..322903.744 rows=6485253 loops=1)
-> Sort (cost=121923.10..122319.15 rows=158417
width=24) (actual time=265953.080..266123.084 rows=128405 loops=1)
Sort Key: e.id
-> Bitmap Heap Scan on event e
(cost=1030.46..108241.13 rows=158417 width=24) (actual
time=4750.055..265213.072 rows=128405 loops=1)
Recheck Cond: (obj_id = 1039)
-> Bitmap Index Scan on
idx_event__obj_id (cost=0.00..1030.46 rows=158417 width=0) (actual
time=4730.055..4730.055 rows=128405 loops=1)
Index Cond: (obj_id = 1039)
-> Hash (cost=1.39..1.39 rows=39 width=14) (actual
time=0.000..0.000 rows=39 loops=1)
-> Seq Scan on event_type_attr ta
(cost=0.00..1.39 rows=39 width=14) (actual time=0.000..0.000 rows=39
loops=1)
-> Hash (cost=8.17..8.17 rows=2 width=108) (actual
time=20.000..20.000 rows=24 loops=1)
-> Nested Loop (cost=2.02..8.17 rows=2 width=108)
(actual time=20.000..20.000 rows=24 loops=1)
-> Seq Scan on "class" c (cost=0.00..3.19
rows=1 width=31) (actual time=0.000..0.000 rows=1 loops=1)
Filter: (lower((pkg_name)::text) ~~
'bric::biz::asset::business::story'::text)
-> Bitmap Heap Scan on event_type t
(cost=2.02..4.92 rows=5 width=85) (actual time=20.000..20.000 rows=24
loops=1)
Recheck Cond: (t.class__id = "outer".id)
-> Bitmap Index Scan on
fkx_class__event_type (cost=0.00..2.02 rows=5 width=0) (actual
time=20.000..20.000 rows=24 loops=1)
Index Cond: (t.class__id = "outer".id)
SubPlan
-> Seq Scan on alert (cost=0.00..10.90 rows=90 width=4)
(actual time=0.000..0.000 rows=0 loops=1)
Total runtime: 599806.942 ms

On Apr 20, 2009, at 8:15 AM, Greg Heo wrote:

> I tracked it down to Bric::App::Callback::Profile::Story->cancel.
> The Bric::Util::Event->list() call is what takes a really long time.
> As Bret mentioned, if where the story came from (desk, shelf) could
> be stored somewhere on checkout, it would be easy to put it back
> when the checkout is cancelled. Of course I have no idea where this
> should/can be stored.

Neither do I. I don't think it's very practical.

> I think the table is indexed properly and it's just a lot of records
> in the event table slowing things down. Here's the Event->list()
> query plan anyway, just in case.

That looks pretty ridiculous. Here's the code in question:

# If the story was last recalled from the library, then
remove it
# from the desk and workflow. We can tell this because there
will
# only be one story_moved event and one story_checkout event
# since the last story_add_workflow event.
my @events = Bric::Util::Event->list({
class => ref $story,
obj_id => $story->get_id
});
my ($desks, $cos) = (0, 0);
while (@events && $events[0]->get_key_name ne
'story_add_workflow') {
my $kn = shift(@events)->get_key_name;
if ($kn eq 'story_moved') {
$desks++;
} elsif ($kn eq 'story_checkout') {
$cos++
}
}


The problem is that it fetches *all* of the events when it only really
needs those going back as far as the last story_add_workflow event. So
the thing to do is to rewrite this query to only select events back
that far.

Best,

David