Thread: Stranger than fiction...

Sorry for the double, but I just stripped down my query on my status
table and saw some interesting results....

          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

This table currently has 224 rows of data in it.

The following queries *ALL* take approx.  .433 seconds to run.

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' ;
select * from status s where s.site_id = 18 and s.host_id = 49 and
s.product = 'BETA';
select * from status s where s.site_id = 18 and s.host_id = 49;
select * from status s where s.site_id = 18;
select * from status;

Nothing gets triggered on a select off of this table.  This table did
have a view attached, but I dropped the view with the same results.

So, I'm totally baffled as to how a simple select * on a 224-row table
could take almost half a second to execute!  Please help the neophyte.
=)

Thank you,
Fran

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

Fran Fabrizio <ffabrizio@exchange.webmd.net> writes:


> 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:

If a table is small (you have ~200 rows in it, right?) a sequential
scan will usually win even when there is an index.  Enjoy your
improved query time and be happy.  ;)

-Doug
--
The rain man gave me two cures; he said jump right in,
The first was Texas medicine--the second was just railroad gin,
And like a fool I mixed them, and it strangled up my mind,
Now people just get uglier, and I got no sense of time...          --Dylan

> This table currently has 224 rows of data in it.
>
> The following queries *ALL* take approx.  .433 seconds to run.
>
> 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' ;
> select * from status s where s.site_id = 18 and s.host_id = 49 and
> s.product = 'BETA';
> select * from status s where s.site_id = 18 and s.host_id = 49;
> select * from status s where s.site_id = 18;
> select * from status;
>
> Nothing gets triggered on a select off of this table.  This table did
> have a view attached, but I dropped the view with the same results.
>
> So, I'm totally baffled as to how a simple select * on a 224-row table
> could take almost half a second to execute!  Please help the neophyte.
> =)

Have you VACUUMed the table (with or without ANALYZE)? Beyond that, we
really need the results of the EXPLAIN to see what the database is doing and
how to improve on that.

Greg