Re: query speed depends on lifetime of frozen db?

On Fri, 27 Sep 2002, Martijn van Oosterhout wrote:

> On Fri, Sep 27, 2002 at 12:50:14PM +0300, Andriy Tkachuk wrote:
> > On Fri, 27 Sep 2002, Martijn van Oosterhout wrote:
> >
> > > On Fri, Sep 27, 2002 at 11:49:08AM +0300, Andriy Tkachuk wrote:
> > > > On Fri, 27 Sep 2002, Shridhar Daithankar wrote:
> > > > > was that vacuum full or vacuum analyze? Vacuum full should help in this case..
> > > >
> > > > it was full with analize
> > > > That's what i want to say, that this is very strange for me that vacuum
> > > > not helpfull in this situation!
> > >
> > > Ok, can you post the result of VACUUM FULL VERBOSE ANALYSE ?
>
> <snip>
>
> Um, from the looks of that output, it seems your entire DB is less than 2MB,
> right? So it should be totally cached. So it must be your query at fault.
> What is the output of EXPLAIN ANALYSE <query>;

db ~ 10M, but i like your guess.

my OS:
Linux 2.4.9-13custom #1 Fri Feb 15 20:03:52 EST 2002 i686

There is EXPLAIN ANALYSE when query is heavy:

NOTICE: QUERY PLAN:

Sort (cost=26.09..26.09 rows=123 width=89) (actual time=168091.22..168091.31 rows=119 loops=1)
-> Hash Join (cost=1.27..21.81 rows=123 width=89) (actual time=1404.81..168090.21 rows=119 loops=1)
-> Seq Scan on users u (cost=0.00..18.07 rows=123 width=81) (actual time=0.14..5.67 rows=119 loops=1)
-> Hash (cost=1.22..1.22 rows=22 width=8) (actual time=0.24..0.24 rows=0 loops=1)
-> Seq Scan on plans p (cost=0.00..1.22 rows=22 width=8) (actual time=0.12..0.19 rows=22 loops=1)
SubPlan
-> Seq Scan on plans (cost=0.00..1.27 rows=1 width=7) (actual time=0.09..0.11 rows=1 loops=119)
-> Aggregate (cost=23.80..23.80 rows=1 width=4) (actual time=0.93..0.94 rows=1 loops=119)
-> Seq Scan on oplaty (cost=0.00..23.80 rows=1 width=4) (actual time=0.87..0.91 rows=0 loops=119)
-> Aggregate (cost=20.84..20.84 rows=1 width=4) (actual time=0.85..0.86 rows=1 loops=119)
-> Seq Scan on oplaty (cost=0.00..20.84 rows=1 width=4) (actual time=0.83..0.84 rows=0 loops=119)
-> Aggregate (cost=22.32..22.32 rows=1 width=4) (actual time=0.84..0.85 rows=1 loops=119)
-> Seq Scan on oplaty (cost=0.00..22.32 rows=1 width=4) (actual time=0.83..0.84 rows=0 loops=119)
-> Aggregate (cost=216.00..216.00 rows=1 width=4) (actual time=1.27..1.27 rows=1 loops=119)
-> Index Scan using bill_uid on bills (cost=0.00..215.88 rows=47 width=4) (actual time=0.25..1.18 rows=39 loops=119)
-> Aggregate (cost=215.68..215.68 rows=1 width=4) (actual time=0.69..0.69 rows=1 loops=119)
-> Index Scan using bill_uid on bills (cost=0.00..215.61 rows=30 width=4) (actual time=0.07..0.62 rows=32 loops=119)
-> Aggregate (cost=215.68..215.68 rows=1 width=4) (actual time=0.69..0.69 rows=1 loops=119)
-> Index Scan using bill_uid on bills (cost=0.00..215.61 rows=30 width=4) (actual time=0.06..0.62 rows=32 loops=119)
-> Aggregate (cost=215.47..215.47 rows=1 width=4) (actual time=0.43..0.43 rows=1 loops=119)
-> Index Scan using bill_uid on bills (cost=0.00..215.47 rows=1 width=4) (actual time=0.23..0.41 rows=3 loops=119)
-> Aggregate (cost=215.47..215.47 rows=1 width=4) (actual time=0.44..0.44 rows=1 loops=119)
-> Index Scan using bill_uid on bills (cost=0.00..215.47 rows=1 width=4) (actual time=0.23..0.43 rows=3 loops=119)
-> Aggregate (cost=215.47..215.47 rows=1 width=4) (actual time=0.43..0.43 rows=1 loops=119)
-> Index Scan using bill_uid on bills (cost=0.00..215.47 rows=1 width=4) (actual time=0.14..0.41 rows=4 loops=119)
-> Aggregate (cost=215.47..215.47 rows=1 width=4) (actual time=0.43..0.43 rows=1 loops=119)
-> Index Scan using bill_uid on bills (cost=0.00..215.47 rows=1 width=4) (actual time=0.14..0.41 rows=4 loops=119)
-> Aggregate (cost=215.47..215.47 rows=1 width=4) (actual time=0.41..0.42 rows=1 loops=119)
-> Index Scan using bill_uid on bills (cost=0.00..215.47 rows=1 width=4) (actual time=0.40..0.40 rows=0 loops=119)
-> Aggregate (cost=216.44..216.44 rows=1 width=4) (actual time=0.76..0.76 rows=1 loops=119)
-> Index Scan using bill_uid on bills (cost=0.00..216.44 rows=2 width=4) (actual time=0.61..0.74 rows=4 loops=119)
-> Aggregate (cost=215.61..215.61 rows=1 width=4) (actual time=0.43..0.43 rows=1 loops=119)
-> Index Scan using bill_uid on bills (cost=0.00..215.61 rows=1 width=4) (actual time=0.28..0.42 rows=1 loops=119)
Total runtime: 168092.92 msec

EXPLAIN

and there is, when query is light:

NOTICE: QUERY PLAN:

Sort (cost=28.90..28.90 rows=1 width=136) (actual time=3863.35..3863.43 rows=119 loops=1)
-> Hash Join (cost=1.27..28.89 rows=1 width=136) (actual time=74.98..3861.69 rows=119 loops=1)
-> Seq Scan on users u (cost=0.00..27.50 rows=10 width=128) (actual time=0.17..5.26 rows=119 loops=1)
-> Hash (cost=1.22..1.22 rows=22 width=8) (actual time=0.16..0.16 rows=0 loops=1)
-> Seq Scan on plans p (cost=0.00..1.22 rows=22 width=8) (actual time=0.03..0.11 rows=22 loops=1)
SubPlan
-> Seq Scan on plans (cost=0.00..1.27 rows=1 width=32) (actual time=0.03..0.05 rows=1 loops=119)
-> Aggregate (cost=35.00..35.00 rows=1 width=4) (actual time=0.91..0.91 rows=1 loops=119)
-> Seq Scan on oplaty (cost=0.00..35.00 rows=1 width=4) (actual time=0.85..0.89 rows=0 loops=119)
-> Aggregate (cost=30.00..30.00 rows=1 width=4) (actual time=0.85..0.85 rows=1 loops=119)
-> Seq Scan on oplaty (cost=0.00..30.00 rows=1 width=4) (actual time=0.83..0.84 rows=0 loops=119)
-> Aggregate (cost=32.50..32.50 rows=1 width=4) (actual time=0.84..0.84 rows=1 loops=119)
-> Seq Scan on oplaty (cost=0.00..32.50 rows=1 width=4) (actual time=0.83..0.83 rows=0 loops=119)
-> Aggregate (cost=12.39..12.39 rows=1 width=4) (actual time=1.06..1.06 rows=1 loops=119)
-> Index Scan using bill_uid on bills (cost=0.00..12.38 rows=1 width=4) (actual time=0.07..0.98 rows=39 loops=119)
-> Aggregate (cost=12.37..12.37 rows=1 width=4) (actual time=0.69..0.69 rows=1 loops=119)
-> Index Scan using bill_uid on bills (cost=0.00..12.37 rows=1 width=4) (actual time=0.07..0.62 rows=32 loops=119)
-> Aggregate (cost=12.37..12.37 rows=1 width=4) (actual time=0.69..0.69 rows=1 loops=119)
-> Index Scan using bill_uid on bills (cost=0.00..12.37 rows=1 width=4) (actual time=0.06..0.62 rows=32 loops=119)
-> Aggregate (cost=12.37..12.37 rows=1 width=4) (actual time=0.43..0.43 rows=1 loops=119)
-> Index Scan using bill_uid on bills (cost=0.00..12.36 rows=1 width=4) (actual time=0.23..0.41 rows=3 loops=119)
-> Aggregate (cost=12.37..12.37 rows=1 width=4) (actual time=0.43..0.43 rows=1 loops=119)
-> Index Scan using bill_uid on bills (cost=0.00..12.36 rows=1 width=4) (actual time=0.23..0.41 rows=3 loops=119)
-> Aggregate (cost=12.37..12.37 rows=1 width=4) (actual time=0.43..0.44 rows=1 loops=119)
-> Index Scan using bill_uid on bills (cost=0.00..12.36 rows=1 width=4) (actual time=0.14..0.41 rows=4 loops=119)
-> Aggregate (cost=12.37..12.37 rows=1 width=4) (actual time=0.43..0.43 rows=1 loops=119)
-> Index Scan using bill_uid on bills (cost=0.00..12.36 rows=1 width=4) (actual time=0.14..0.41 rows=4 loops=119)
-> Aggregate (cost=12.37..12.37 rows=1 width=4) (actual time=0.41..0.41 rows=1 loops=119)
-> Index Scan using bill_uid on bills (cost=0.00..12.36 rows=1 width=4) (actual time=0.40..0.40 rows=0 loops=119)
-> Aggregate (cost=12.41..12.41 rows=1 width=4) (actual time=0.73..0.73 rows=1 loops=119)
-> Index Scan using bill_uid on bills (cost=0.00..12.41 rows=1 width=4) (actual time=0.58..0.71 rows=4 loops=119)
-> Aggregate (cost=12.37..12.37 rows=1 width=4) (actual time=0.42..0.42 rows=1 loops=119)
-> Index Scan using bill_uid on bills (cost=0.00..12.37 rows=1 width=4) (actual time=0.27..0.41 rows=1 loops=119)
Total runtime: 3865.89 msec

EXPLAIN