Interesting incosistent query timing

From: Ernest E Vogelsinger <ernest(at)vogelsinger(dot)at>
To: pgsql-performance(at)postgresql(dot)org, pgsql-general(at)postgresql(dot)org
Subject: Interesting incosistent query timing
Date: 2003-06-16 22:46:54
Message-ID: 5.1.1.6.2.20030617003809.02deaa78@mail.vogelsinger.at
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-general pgsql-performance

Hi,

I am researching some interesting inconsistent query timing and hope some
of the gurus hanging out here might help me shed a light on this...

The table:
Column | Type | Modifiers

--------+--------------------------+----------------------------------------
------------
rid | integer | not null default
nextval('rv2_mdata_id_seq'::text)
pid | integer |
owid | integer |
ioid | integer |
dcid | character varying |
dsid | character varying |
drid | integer |
usg | integer |
idx | character varying |
env | integer |
nxid | integer |
ci | integer |
cd | numeric(21,6) |
cr | real |
cts | timestamp with time zone |
cst | character varying |
ctx | text |
cbl | oid |
acl | text |
Indexes: id_mdata_dictid,
id_mdata_dictid_dec,
id_mdata_dictid_int,
id_mdata_dictid_real,
id_mdata_dictid_string,
id_mdata_dictid_text,
id_mdata_dictid_timestamp,
id_mdata_dowid,
id_mdata_ioid,
id_mdata_owid
Primary key: rv2_mdata_pkey

Index "id_mdata_dictid_string"
Column | Type
--------+-------------------
dcid | character varying
dsid | character varying
drid | integer
nxid | integer
cst | character varying
btree
Index predicate: ((usg & 16) = 16)

The query:
explain analyze verbose
select distinct t1.owid
from rv2_mdata t1
where t1.dcid='ADDR' and t1.dsid='AUXDICT' and t1.drid=110 and
t1.usg & 16 = 16
and t1.nxid = 0
and t1.cst ilike '%redist%'
and t1.owid > 10
;

For the first time run it executes in 1.5 - 2 seconds. From the second
time, only 10 msec are needed for the same result:

Unique (cost=3.84..3.84 rows=1 width=4) (actual time=1569.36..1569.39
rows=11 loops=1)
-> Sort (cost=3.84..3.84 rows=1 width=4) (actual time=1569.36..1569.37
rows=11 loops=1)
-> Index Scan using id_mdata_dictid_string on rv2_mdata t1
(cost=0.00..3.83 rows=1 width=4) (actual time=17.02..1569.22 rows=11 loops=1)
Total runtime: 1569.50 msec

Unique (cost=3.84..3.84 rows=1 width=4) (actual time=10.51..10.53 rows=11
loops=1)
-> Sort (cost=3.84..3.84 rows=1 width=4) (actual time=10.51..10.51
rows=11 loops=1)
-> Index Scan using id_mdata_dictid_string on rv2_mdata t1
(cost=0.00..3.83 rows=1 width=4) (actual time=0.60..10.43 rows=11 loops=1)
Total runtime: 10.64 msec

If any of the "dcid", "dsid", or "drid" constraint values are altered, the
query starts again at 1.5 - 2 secs, then drops to 10.5 msec again.

Even after restarting PostgreSQL, the number is lower (~50 msec) than when
running for the first time.

I really would like to get a consistent timing here (the lower the better
of course) since these queries will happen quite often within our
application, and I need a consistent and predictable timing (this being a
core component).

This is postgresql 7.2.1 on RH72.

Any clues? Thanks for insights,

--
>O Ernest E. Vogelsinger
(\) ICQ #13394035
^ http://www.vogelsinger.at/

Responses

Browse pgsql-general by date

  From Date Subject
Next Message Dick Wieland 2003-06-16 22:49:50 pg_options in postgres 7.3.2
Previous Message weigelt 2003-06-16 22:15:22 Re: RE : full featured alter table?

Browse pgsql-performance by date

  From Date Subject
Next Message Manfred Koizar 2003-06-16 23:45:58 Re: Interesting incosistent query timing
Previous Message Jim C. Nasby 2003-06-16 22:45:27 Re: sequential scans on few columns tables