Index Scan taking long time - Mailing list pgsql-performance

Hi,

I have been trying to fix a performance issue that we have which I have
tracked down to index scans being done on a particular table (or set of
tables):

The following query:
explain analyze select *
FROM inbound.event_20090526 e
LEFT OUTER JOIN inbound.internal_host i ON (e.mta_host_id = i.id)
LEFT OUTER JOIN inbound.internal_host iaa ON (e.aamta_host_id = iaa.id)
LEFT OUTER JOIN inbound.event_status es ON (e.event_status_id = es.id)
LEFT OUTER JOIN inbound.threat t ON (e.threat_id = t.id), inbound.domain
d, inbound.event_type et
WHERE e.domain_id = d.id
AND e.event_type_id = et.id
AND d.name IN (
    'testdomain.com'
);


Does this:

QUERY
PLAN


--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Nested Loop Left Join  (cost=0.00..10887.03 rows=8 width=2021) (actual
time=50.352..14378.603 rows=3453 loops=1)
   ->  Nested Loop Left Join  (cost=0.00..10882.23 rows=8 width=1985)
(actual time=50.346..14372.820 rows=3453 loops=1)
         ->  Nested Loop Left Join  (cost=0.00..10877.43 rows=8
width=1949) (actual time=50.336..14358.101 rows=3453 loops=1)
               ->  Nested Loop Left Join  (cost=0.00..10872.63 rows=8
width=1801) (actual time=50.321..14344.603 rows=3453 loops=1)
                     ->  Nested Loop  (cost=0.00..10867.83 rows=8
width=1764) (actual time=50.315..14336.979 rows=3453 loops=1)
                           ->  Nested Loop  (cost=0.00..10863.03 rows=8
width=1728) (actual time=50.288..14308.368 rows=3453 loops=1)
                                 ->  Index Scan using domain_name_idx on
domain d  (cost=0.00..6.63 rows=1 width=452) (actual time=0.049..0.080
rows=1 loops=1)
                                       Index Cond: ((name)::text =
'testdomain.com'::text)
                                 ->  Index Scan using
event_20090526_domain_idx on event_20090526 e  (cost=0.00..10694.13
rows=3606 width=1276) (actual time=50.233..14305.211 rows=3453 loops=1)
                                       Index Cond: (e.domain_id = d.id)
                           ->  Index Scan using event_type_pkey on
event_type et  (cost=0.00..0.56 rows=1 width=36) (actual
time=0.006..0.006 rows=1 loops=3453)
                                 Index Cond: (et.id = e.event_type_id)
                     ->  Index Scan using threat_pkey on threat t
(cost=0.00..0.56 rows=1 width=37) (actual time=0.000..0.000 rows=0
loops=3453)
                           Index Cond: (e.threat_id = t.id)
               ->  Index Scan using event_status_pkey on event_status
es  (cost=0.00..0.56 rows=1 width=148) (actual time=0.002..0.002 rows=1
loops=3453)
                     Index Cond: (e.event_status_id = es.id)
         ->  Index Scan using internal_host_pkey on internal_host iaa
(cost=0.00..0.56 rows=1 width=36) (actual time=0.002..0.003 rows=1
loops=3453)
               Index Cond: (e.aamta_host_id = iaa.id)
   ->  Index Scan using internal_host_pkey on internal_host i
(cost=0.00..0.56 rows=1 width=36) (actual time=0.000..0.000 rows=0
loops=3453)
         Index Cond: (e.mta_host_id = i.id)
 Total runtime: 14380.000 ms

If the same query is done straight away again we get:

QUERY
PLAN


---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Nested Loop Left Join  (cost=0.00..10887.03 rows=8 width=2021) (actual
time=0.165..67.388 rows=3453 loops=1)
   ->  Nested Loop Left Join  (cost=0.00..10882.23 rows=8 width=1985)
(actual time=0.162..61.973 rows=3453 loops=1)
         ->  Nested Loop Left Join  (cost=0.00..10877.43 rows=8
width=1949) (actual time=0.156..49.756 rows=3453 loops=1)
               ->  Nested Loop Left Join  (cost=0.00..10872.63 rows=8
width=1801) (actual time=0.148..37.522 rows=3453 loops=1)
                     ->  Nested Loop  (cost=0.00..10867.83 rows=8
width=1764) (actual time=0.146..31.920 rows=3453 loops=1)
                           ->  Nested Loop  (cost=0.00..10863.03 rows=8
width=1728) (actual time=0.129..10.325 rows=3453 loops=1)
                                 ->  Index Scan using domain_name_idx on
domain d  (cost=0.00..6.63 rows=1 width=452) (actual time=0.099..0.139
rows=1 loops=1)
                                       Index Cond: ((name)::text =
'rhe.com.au'::text)
                                 ->  Index Scan using
event_20090526_domain_idx on event_20090526 e  (cost=0.00..10694.13
rows=3606 width=1276) (actual time=0.027..7.510 rows=3453 loops=1)
                                       Index Cond: (e.domain_id = d.id)
                           ->  Index Scan using event_type_pkey on
event_type et  (cost=0.00..0.56 rows=1 width=36) (actual
time=0.004..0.005 rows=1 loops=3453)
                                 Index Cond: (et.id = e.event_type_id)
                     ->  Index Scan using threat_pkey on threat t
(cost=0.00..0.56 rows=1 width=37) (actual time=0.000..0.000 rows=0
loops=3453)
                           Index Cond: (e.threat_id = t.id)
               ->  Index Scan using event_status_pkey on event_status
es  (cost=0.00..0.56 rows=1 width=148) (actual time=0.002..0.002 rows=1
loops=3453)
                     Index Cond: (e.event_status_id = es.id)
         ->  Index Scan using internal_host_pkey on internal_host iaa
(cost=0.00..0.56 rows=1 width=36) (actual time=0.002..0.002 rows=1
loops=3453)
               Index Cond: (e.aamta_host_id = iaa.id)
   ->  Index Scan using internal_host_pkey on internal_host i
(cost=0.00..0.56 rows=1 width=36) (actual time=0.000..0.000 rows=0
loops=3453)
         Index Cond: (e.mta_host_id = i.id)
 Total runtime: 68.475 ms

Which suggests to me that it takes the remainder of the 14300ms in the
first query to read the event_20090526_domain_idx index in from disk.

The table has 2 million records in it, and the index has a physical size
on disk of 44MB.  The box this is running on is rather powerful having 8
cores, 16GB ram, and stripped disks.

What I am wondering is is there any reason why this would be taking so
long?  Or what can be done to fix this / track down the issue more?

Cheers
Bryce