Re: Stranger than fiction - EXPLAIN results - Mailing list pgsql-general

I'm sorry that I did not send the EXPLAIN results along with my original email,
I had no idea this command existed (I'm a first-week rookie with postgres!)

Also, I did not know about vacuum, and apparently, that was the culprit!  After
vacuum'ing, times went from .433 sec/query to .001.  Holy moly!  I read up on
vacuum in the Postgres book we have, and I guess since I've been doing so much
testing, I've been really updating a LOT of rows in the table, because here's
what the vacuum results looked like:

010502.11:13:46.469  [3029] StartTransactionCommand
010502.11:13:46.469  [3029] query: vacuum status;
010502.11:13:46.469  [3029] ProcessUtility: vacuum status;
010502.11:13:46.470  [3029] DEBUG:  --Relation status--
010502.11:13:46.978  [3029] DEBUG:  Pages 5700: Changed 0, reaped 5700, Empty
0, New 0; Tup 224: Vac 364719, Keep/VTL 0/0, Crash 0, UnUsed 0, MinLen 100,
MaxLen 208; Re-using: Free/Avail. Space 45161576/45149008; EndEmpty/Avail.
Pages 1/5698. CPU 0.25s/0.25u sec.
010502.11:13:46.980  [3029] DEBUG:  Index status_5_column_index: Pages 4;
Tuples 224: Deleted 0. CPU 0.01s/0.00u sec.
010502.11:13:50.641  [3029] DEBUG:  Index status_site_id_key: Pages 920; Tuples
224: Deleted 364719. CPU 0.24s/3.36u sec.
010502.11:13:54.335  [3029] DEBUG:  Index status_host_id_key: Pages 930; Tuples
224: Deleted 364719. CPU 0.17s/3.46u sec.
010502.11:13:55.252  [3029] DEBUG:  Rel status: Pages: 5700 --> 4; Tuple(s)
moved: 224. CPU 0.78s/0.14u sec.
010502.11:13:55.256  [3029] DEBUG:  Index status_5_column_index: Pages 6;
Tuples 224: Deleted 224. CPU 0.00s/0.00u sec.
010502.11:13:55.307  [3029] DEBUG:  Index status_site_id_key: Pages 920; Tuples
224: Deleted 224. CPU 0.05s/0.00u sec.
010502.11:13:55.358  [3029] DEBUG:  Index status_host_id_key: Pages 930; Tuples
224: Deleted 224. CPU 0.05s/0.00u sec.
010502.11:13:55.385  [3029] CommitTransactionCommand

Can someone explain to me these results?  What does it mean when it says
Deleted 364719 of Index status_site_id_key, for example?  And then later on it
goes back to that index and deletes another 224.  What is going on internally?

Also, after vacuuming the table, I reran my select query....

010502.11:22:57.579  [3029] StartTransactionCommand
010502.11:22:57.579  [3029] query: select * from status s where s.site_id = 18
and s.host_id = 49
and s.product = 'BETA' and s.class = 'APPS' and s.subclass = 'MONITOR' ;
010502.11:22:57.581  [3029] ProcessQuery
010502.11:22:57.582  [3029] CommitTransactionCommand

As you can see, .001s execution time!  However - EXPLAIN still shows:

010502.11:24:05.001  [3029] StartTransactionCommand
010502.11:24:05.002  [3029] query: explain select * from status s where
s.site_id = 18 and s.host_id = 49
and s.product = 'BETA' and s.class = 'APPS' and s.subclass = 'MONITOR' ;
010502.11:24:05.002  [3029] ProcessUtility: explain select * from status s
where s.site_id = 18 and s.host_id = 49
and s.product = 'BETA' and s.class = 'APPS' and s.subclass = 'MONITOR' ;
010502.11:24:05.003  [3029] NOTICE:  QUERY PLAN:

Seq Scan on status s  (cost=0.00..9.04 rows=1 width=84)

010502.11:24:05.003  [3029] CommitTransactionCommand

Which is incorrect because it should be using my index, shouldn't it?  Here is
how I created my index:

monitoring=# create index status_5_column_index on status (site_id, host_id,
product, class, subclass);

And a desc. of the table shows the index is there:

monitoring=# \d status
          Table "status"
 Attribute |   Type    | Modifier
-----------+-----------+----------
 site_id   | bigint    | not null
 host_id   | bigint    | not null
 product   | varchar() | not null
 class     | varchar() | not null
 subclass  | varchar() | not null
 status    | varchar() | not null
 msg       | varchar() |
 tstamp    | timestamp |
Indices: status_5_column_index,
         status_host_id_key,
         status_site_id_key

monitoring=#

So it's puzzling me why it's still doing a Seq. Scan vs. an Index Scan.  Any
ideas?

Thanks,
Fran