Thread: Slow SELECT

I am running a SELECT to get all tuples within a given date range. This
query is much slwoer than i expected - am i missing something?

I have a table 'meta' with a column 'in_date' of type timestamp(0), i
am trying to select all
records within a given date range. I have an index on 'in_date' and I
also have an index on date(in_date). The queries I am doing are between
dates rather than timestamps.

Immeadiately prior to running the queries shown below a VACUUM ANALYZE
was run.

The query planner seems to be out by a factor of 10 for cost and number
of rows. Is this this because of the slow performance?

I have 6 million records. With dates spread fairly evenly between the
end of 2001 and now.

I was very suprised to see the query take over 20 minutes when using
the date(in_date) index. And more suprised to see the seq_scan over in_
date using timestamps take only 10 minutes.

Both are taking too long in my opinion! I was hoping for less than 10
seconds. Is this too optimistic?

Any suggestions much appreciated.

I am using RH_AS_3 on IBM x450 quad xeon ia64, 4GB mem (1GB shared
buffers for
postmaster)
When running queries the processor its running on sits down at 15-20%
usage and the iowait goes up to 80-99% (fiber attached raid(0) yes i
know its not resiliant).

testdb=# EXPLAIN ANALYZE  SELECT item_id, in_date FROM meta WHERE date(
in_date) >= '2002-03-01' AND date(in_date) < '2002-04-01' order by in_
date DESC;
    QUERY PLAN

------------------------------------------------------------------------
------------------------------------------------------------------------
------------------
Sort  (cost=122755.65..122830.64 rows=29996 width=50) (actual time=
1248326.17..1248608.39 rows=261305 loops=1)
Sort Key: in_date
->  Index Scan using meta_in_date_date_index on meta  (cost=0.00..
120525.09 rows=29996 width=50) (actual time=0.00..1244835.94 rows=
261305 loops=1)
Index Cond: ((date(in_date) >= '2002-03-01'::date) AND (date(in_date) <
'2002-04-01'::date))
Total runtime: 1248887.70 msec
(5 rows)


Here are the stats on the in_date column if they're any use...

testdb=# SELECT * FROM pg_stats WHERE tablename = 'meta' and attname = '
in_date';
schemaname | tablename | attname  | null_frac | avg_width | n_distinct |
most_common_vals | most_common_freqs |
histogram_bounds                                              |
correlation
------------+-----------+----------+-----------+-----------+------------
+------------------+-------------------+--------------------------------
------------------------------------------------------------------------
------------------------------------------------------------------------
---------------------------------------------------------------------+--
------------
public     | meta | in_date |         0 |         8 |         -1 |
|                   | {"2001-10-18 17:28:23","2001-12-28 19:31:06","
2002-03-14 19:59:08","2002-05-27 08:28:04","2002-07-31 14:06:06","2002-
10-09 19:09:49","2002-12-21 03:58:46","2003-03-02 21:41:37","2003-05-09
16:12:39","2003-07-22 05:13:18","2003-09-30 13:48:04"} | -0.000184019
(1 row)


Here is the same query as above but using timestamp(0)'s instead of
dates.

testdb=# EXPLAIN ANALYZE  SELECT item_id, in_date FROM meta WHERE in_
date >= '2002-03-01' AND in_date < '2002-04-01' order by in_date DESC;
QUERY PLAN
------------------------------------------------------------------------
------------------------------------------------------------------------
--------
Sort  (cost=797371.98..797995.09 rows=249246 width=50) (actual time=
616906.25..617183.58 rows=261305 loops=1)
Sort Key: in_date
->  Seq Scan on meta  (cost=0.00..775030.55 rows=249246 width=50) (
actual time=19.53..611541.03 rows=261305 loops=1)
Filter: ((in_date >= '2002-03-01 00:00:00'::timestamp without time zone)
AND (in_date < '2002-04-01 00:00:00'::timestamp without time zone))
Total runtime: 617446.29 msec
(5 rows)


--

psql-mail@freeuk.com writes:
> I am running a SELECT to get all tuples within a given date range. This
> query is much slwoer than i expected - am i missing something?

Well, it seems to be running at about 5 msec/row, which would be quite
respectable if each fetch required another disk seek.  I'm wondering why
you are (apparently) not managing to get more than one row per page
fetched.  What are your configuration settings --- particularly
shared_buffers?  Could we see the output of VACUUM VERBOSE for this
table?

            regards, tom lane

On Fri, 2003-10-03 at 17:50, Tom Lane wrote:
> psql-mail@freeuk.com writes:
> > I am running a SELECT to get all tuples within a given date range. This
> > query is much slwoer than i expected - am i missing something?
>
> Well, it seems to be running at about 5 msec/row, which would be quite
> respectable if each fetch required another disk seek.  I'm wondering why
> you are (apparently) not managing to get more than one row per page
> fetched.  What are your configuration settings --- particularly
> shared_buffers?  Could we see the output of VACUUM VERBOSE for this
> table?
>
>             regards, tom lane
>
> ---------------------------(end of broadcast)---------------------------
> TIP 1: subscribe and unsubscribe commands go to majordomo@postgresql.org
Tom,
Thanks for your comments.

Here is the information you requested:

The date column is in the public.meta table.
public.data contains bodies of text to be searched.

DATA:

Lines from postgresql.conf that don't start with a '#':

tcpip_socket = true
shared_buffers = 126976     #992 MB
sort_mem = 36864                #36 MB
vacuum_mem = 73696              #72 MB

stats_start_collector = true
stats_command_string = true
stats_row_level = true
stats_block_level = true

LC_MESSAGES = 'en_US.UTF-8'
LC_MONETARY = 'en_US.UTF-8'
LC_NUMERIC = 'en_US.UTF-8'
LC_TIME = 'en_US.UTF-8'



testdb=# VACUUM VERBOSE;
INFO:  --Relation pg_catalog.pg_conversion--
INFO:  Pages 2: Changed 0, Empty 0; Tup 114: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_catalog.pg_depend--
INFO:  Pages 22: Changed 0, Empty 0; Tup 2947: Vac 0, Keep 0, UnUsed 1.
        Total CPU 0.00s/0.00u sec elapsed 0.03 sec.
INFO:  --Relation pg_catalog.pg_attrdef--
INFO:  Pages 1: Changed 0, Empty 0; Tup 6: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_toast.pg_toast_16384--
INFO:  Pages 0: Changed 0, Empty 0; Tup 0: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_catalog.pg_constraint--
INFO:  Pages 1: Changed 0, Empty 0; Tup 20: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_toast.pg_toast_16386--
INFO:  Pages 0: Changed 0, Empty 0; Tup 0: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_catalog.pg_database--
INFO:  Pages 1: Changed 0, Empty 0; Tup 4: Vac 0, Keep 0, UnUsed 3.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_toast.pg_toast_1262--
INFO:  Pages 0: Changed 0, Empty 0; Tup 0: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_catalog.pg_description--
INFO:  Pages 12: Changed 0, Empty 0; Tup 1390: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.01 sec.
INFO:  --Relation pg_toast.pg_toast_16416--
INFO:  Pages 0: Changed 0, Empty 0; Tup 0: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_catalog.pg_group--
INFO:  Pages 0: Changed 0, Empty 0; Tup 0: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_toast.pg_toast_1261--
INFO:  Pages 0: Changed 0, Empty 0; Tup 0: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_catalog.pg_proc--
INFO:  Pages 59: Changed 0, Empty 0; Tup 1492: Vac 0, Keep 0, UnUsed
179.
        Total CPU 0.00s/0.00u sec elapsed 0.02 sec.
INFO:  --Relation pg_toast.pg_toast_1255--
INFO:  Pages 0: Changed 0, Empty 0; Tup 0: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_catalog.pg_rewrite--
INFO:  Pages 4: Changed 0, Empty 0; Tup 27: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_toast.pg_toast_16410--
INFO:  Pages 4: Changed 0, Empty 0; Tup 16: Vac 0, Keep 0, UnUsed 1.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_catalog.pg_type--
INFO:  Pages 4: Changed 0, Empty 0; Tup 190: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_catalog.pg_attribute--
INFO:  Pages 18: Changed 0, Empty 0; Tup 1062: Vac 0, Keep 0, UnUsed 7.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_catalog.pg_class--
INFO:  Pages 5: Changed 0, Empty 0; Tup 175: Vac 0, Keep 0, UnUsed 71.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_catalog.pg_inherits--
INFO:  Pages 0: Changed 0, Empty 0; Tup 0: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_catalog.pg_index--
INFO:  Pages 3: Changed 0, Empty 0; Tup 94: Vac 0, Keep 0, UnUsed 1.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_catalog.pg_operator--
INFO:  Pages 14: Changed 0, Empty 0; Tup 643: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_catalog.pg_opclass--
INFO:  Pages 1: Changed 0, Empty 0; Tup 51: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_catalog.pg_am--
INFO:  Pages 1: Changed 0, Empty 0; Tup 4: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_catalog.pg_amop--
INFO:  Pages 1: Changed 0, Empty 0; Tup 180: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_catalog.pg_amproc--
INFO:  Pages 1: Changed 0, Empty 0; Tup 57: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_catalog.pg_language--
INFO:  Pages 1: Changed 0, Empty 0; Tup 3: Vac 0, Keep 0, UnUsed 3.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_catalog.pg_largeobject--
INFO:  Pages 0: Changed 0, Empty 0; Tup 0: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_catalog.pg_shadow--
INFO:  Pages 1: Changed 0, Empty 0; Tup 2: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_toast.pg_toast_1260--
INFO:  Pages 0: Changed 0, Empty 0; Tup 0: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_catalog.pg_aggregate--
INFO:  Pages 1: Changed 0, Empty 0; Tup 60: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_catalog.pg_trigger--
INFO:  Pages 1: Changed 0, Empty 0; Tup 26: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_catalog.pg_listener--
INFO:  Pages 0: Changed 0, Empty 0; Tup 0: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_catalog.pg_cast--
INFO:  Pages 2: Changed 0, Empty 0; Tup 174: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_catalog.pg_namespace--
INFO:  Pages 1: Changed 0, Empty 0; Tup 4: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_catalog.pg_statistic--
INFO:  Pages 17: Changed 0, Empty 0; Tup 164: Vac 0, Keep 0, UnUsed 320.
        Total CPU 0.00s/0.00u sec elapsed 0.04 sec.
INFO:  --Relation pg_toast.pg_toast_16408--
INFO:  Pages 5: Changed 0, Empty 0; Tup 6: Vac 0, Keep 0, UnUsed 15.
        Total CPU 0.00s/0.00u sec elapsed 0.02 sec.
INFO:  --Relation public.meta--
INFO:  Pages 685043: Changed 0, Empty 8; Tup 5999170: Vac 0, Keep 0,
UnUsed 5999170.
        Total CPU 18.06s/3.61u sec elapsed 612.91 sec.
INFO:  --Relation pg_toast.pg_toast_16989--
INFO:  Pages 1: Changed 0, Empty 0; Tup 4: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation public.data--
INFO:  Pages 1359266: Changed 0, Empty 24; Tup 5999174: Vac 0, Keep 0,
UnUsed 1595705.
        Total CPU 33.74s/6.64u sec elapsed 1436.04 sec.
INFO:  --Relation pg_toast.pg_toast_16979--
INFO:  Pages 1154272: Changed 0, Empty 9; Tup 4454208: Vac 0, Keep 0,
UnUsed 1074682.
        Total CPU 28.98s/5.65u sec elapsed 1159.64 sec.
INFO:  --Relation public.sys_id_ng_id_link--
INFO:  Pages 76254: Changed 0, Empty 1; Tup 11960406: Vac 0, Keep 0,
UnUsed 10064.
        Total CPU 1.96s/1.10u sec elapsed 97.64 sec.
INFO:  --Relation public.src_grp--
INFO:  Pages 202: Changed 0, Empty 0; Tup 23501: Vac 0, Keep 0, UnUsed
0.
        Total CPU 0.00s/0.00u sec elapsed 0.24 sec.
INFO:  --Relation pg_toast.pg_toast_17009--
INFO:  Pages 0: Changed 0, Empty 0; Tup 0: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation public.meta2--
INFO:  Pages 0: Changed 0, Empty 0; Tup 0: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_toast.pg_toast_17041--
INFO:  Pages 0: Changed 0, Empty 0; Tup 0: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation public.data2--
INFO:  Pages 0: Changed 0, Empty 0; Tup 0: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_toast.pg_toast_17031--
INFO:  Pages 0: Changed 0, Empty 0; Tup 0: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation public.src_grp2--
INFO:  Pages 0: Changed 0, Empty 0; Tup 0: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation pg_toast.pg_toast_17061--
INFO:  Pages 0: Changed 0, Empty 0; Tup 0: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  --Relation public.data2_group_link--
INFO:  Pages 0: Changed 0, Empty 0; Tup 0: Vac 0, Keep 0, UnUsed 0.
        Total CPU 0.00s/0.00u sec elapsed 0.00 sec.

Mat wrote:
> Lines from postgresql.conf that don't start with a '#':
>
> tcpip_socket = true
> shared_buffers = 126976     #992 MB
> sort_mem = 36864                #36 MB
> vacuum_mem = 73696              #72 MB

I would suggest scale down shared buffers to 128 or 64MB and set effective cache
size correct. That should help.

HTH

  Shridhar

Mat <psql-mail@freeuk.com> writes:
> On Fri, 2003-10-03 at 17:50, Tom Lane wrote:
>> Well, it seems to be running at about 5 msec/row, which would be quite
>> respectable if each fetch required another disk seek.  I'm wondering why
>> you are (apparently) not managing to get more than one row per page
>> fetched.  What are your configuration settings --- particularly
>> shared_buffers?  Could we see the output of VACUUM VERBOSE for this
>> table?

> Lines from postgresql.conf that don't start with a '#':
> shared_buffers = 126976     #992 MB

As someone else pointed out, that is way too large (unless maybe you
have 4Gb of RAM, and even then I'd not counsel making shared_buffers
that large).

> INFO:  --Relation public.meta--
> INFO:  Pages 685043: Changed 0, Empty 8; Tup 5999170: Vac 0, Keep 0,
> UnUsed 5999170.
>         Total CPU 18.06s/3.61u sec elapsed 612.91 sec.

This shows you've got less than 9 tuples per 8k disk page on average.
Is the table very wide?  If it doesn't seem to you that the tuples
should occupy 1K apiece, it might be that you need to run a VACUUM FULL
to get rid of some excess free space.  (If so, it's a sign that you need
to increase the FSM settings in postgresql.conf and/or run plain VACUUM
more frequently, so that the free space doesn't get away from you
again.)

            regards, tom lane