Re: Interesting incosistent query timing

Ernest,

My guess is that the second execution of the query is
shorter since the data blocks are cached in memory.
When you modify the data then it needs to be read again
from disk which is much slower than from memory.  The
short execution after restarting PostgreSQL seems to
indicate that your data is cached in the Linux buffer
cache.

The only strange thing seems to be that you have so few
rows.  Are you getting the data from a remote machine?
How many bytes does a single row have?  Are they really
large???

Regards,
Nikolaus

On Tue, 17 Jun 2003 00:46:54 +0200, Ernest E
Vogelsinger wrote:

>
> 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/
>
>
>
> ---------------------------(end of
> broadcast)---------------------------
> TIP 7: don't forget to increase your free space map
> settings