Forum OpenACS Q&A: The reason is so slow...

Posted by Jeff Davis on
I think it boils down to the notifications sweeper. notification::sweep::sweep_notifications.select_notifications:
           select notification_id,
            from notifications inner join notification_requests using (type_id, object_id)
              inner join acs_objects on (notification_requests.request_id = acs_objects.object_id)
              left outer join notification_user_map using (notification_id, user_id)
            where sent_date is null
              and creation_date <= notif_date
              and interval_id = 2889
          order by user_id, type_id, notif_date
Has this plan.
Sort  (cost=10373.08..10373.08 rows=2900 width=832) (actual time=603170.17..603170.17 rows=0 loops=1)
  ->  Hash Join  (cost=4815.63..9591.27 rows=2900 width=832) (actual time=603170.08..603170.08 rows=0 loops=1)
        ->  Hash Join  (cost=4622.03..8021.80 rows=2900 width=816) (actual time=1838.57..43845.84 rows=175853 loops=1)
              ->  Merge Join  (cost=1145.89..2066.65 rows=8700 width=804) (actual time=90.50..5933.08 rows=184280 loops=1)
                    ->  Index Scan using notification_requests_t_o_idx on notification_requests  (cost=0.00..751.84 rows=13320 width=20) (actual time=24.68..4322.84 rows=13182 loops=1)
                    ->  Sort  (cost=1145.89..1145.89 rows=2044 width=784) (actual time=50.90..568.95 rows=184276 loops=1)
                          ->  Seq Scan on notifications  (cost=0.00..627.44 rows=2044 width=784) (actual time=0.04..24.12 rows=2044 loops=1)
              ->  Hash  (cost=2758.11..2758.11 rows=104011 width=12) (actual time=499.13..499.13 rows=0 loops=1)
                    ->  Seq Scan on acs_objects  (cost=0.00..2758.11 rows=104011 width=12) (actual time=0.06..349.11 rows=110383 loops=1)
        ->  Hash  (cost=168.08..168.08 rows=10208 width=16) (actual time=7225.23..7225.23 rows=0 loops=1)
              ->  Seq Scan on notification_user_map  (cost=0.00..168.08 rows=10208 width=16) (actual time=24.26..6596.30 rows=290920 loops=1)
Total runtime: 603368.41 msec
Notice the total runtime there. Yikes!

I stopped and ran this by itself with no notifications in the table and the backend required 240mb and took about 8 minutes to return (with the server at load average 0.1 when I started) so it's not a problem with locking or anything going on in the db. The query just really sucks.

I suspect the problem is the notifications table has just grown too big since it's not being purged and I vaguely remember Don maybe having cleaned it out before. Is that right, Don?