First query slow, subsequent queries fast

Hello all,

I observe a strange situation where if I issue a query it is slow, but
subsequent queries are fast. Obviously there are some caching schemes in
effect, but my question is rather about why might the first query be
_that_ slow. I realize that the query itself might be flawed, so probably
you can come up with some input. Here it is:

# query #1:

# explain analyze select * from messages where id in ( select msgkey
from queues where username like 'alk%' and hostname like '%' and time > '26
July 2004' and time < '26 August 2004' and inbound = 1);
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Nested Loop (cost=79.40..82.46 rows=1 width=64) (actual
time=80801.543..99005.053 rows=1996 loops=1)
-> HashAggregate (cost=79.40..79.40 rows=1 width=4) (actual
time=80789.461..80809.255 rows=1996 loops=1)
-> Index Scan using queues_idx_username on queues
(cost=0.00..79.39 rows=3 width=4) (actual time=110.044..80741.483
rows=10320 loops=1)
Index Cond: ((username >= 'alk'::text) AND (username <
'all'::text))
Filter: ((username ~~ 'alk%'::text) AND (hostname ~~
'%'::text) AND ("time" > '2004-07-26 00:00:00+02'::timestamp with time
zone) AND ("time" < '2004-08-26 00:00:00+02'::timestamp with time zone)
AND (inbound = 1))
-> Index Scan using messages_pkey on messages (cost=0.00..3.05 rows=1
width=64) (actual time=9.094..9.100 rows=1 loops=1996)
Index Cond: (messages.id = "outer".msgkey)
Total runtime: 99009.470 ms
(8 rows)

# query #2:

# explain analyze select * from messages where id in ( select msgkey
from queues where username like 'alk%' and hostname like '%' and time > '26
July 2004' and time < '26 August 2004' and inbound = 1);
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Nested Loop (cost=79.40..82.46 rows=1 width=64) (actual
time=155.644..199.876 rows=1996 loops=1)
-> HashAggregate (cost=79.40..79.40 rows=1 width=4) (actual
time=155.604..162.959 rows=1996 loops=1)
-> Index Scan using queues_idx_username on queues
(cost=0.00..79.39 rows=3 width=4) (actual time=0.216..141.122 rows=10320
loops=1)
Index Cond: ((username >= 'alk'::text) AND (username <
'all'::text))
Filter: ((username ~~ 'alk%'::text) AND (hostname ~~
'%'::text) AND ("time" > '2004-07-26 00:00:00+02'::timestamp with time
zone) AND ("time" < '2004-08-26 00:00:00+02'::timestamp with time zone)
AND (inbound = 1))
-> Index Scan using messages_pkey on messages (cost=0.00..3.05 rows=1
width=64) (actual time=0.012..0.014 rows=1 loops=1996)
Index Cond: (messages.id = "outer".msgkey)
Total runtime: 201.371 ms
(8 rows)

--
Sincerely,
Dmitry

--- www.karasik.eu.org ---