Thread: PostgreSQL 7.4 runs slower than 7.3

[I sent this 24 hours ago and it hasn't shown up yet.  I may have used
the wrong address.  If not apologies for the dup.]

I had previously mentioned that queries run much different depending on
whether a VACUUM ANALYZE is done or just a plain ANALYZE.  At the time I
was told that that couldn't be and since I could just use the one that
worked better I didn't worry about it.  Now I have updated my database
to 7.4 and both work badly.  Here is the EXPLAIN output.  Marvin is
running 7.3.6 and romeo is running 7.4.3.  We didn't try to do an
EXPLAIN ANALYZE on romeo because it takes too long but I can assure you
that the numbers are indeed indicative of how long the query takes. 
Does anyone have an explanation?  The data in both cases is exactly the
same as is the table definitions and indexes.

******************* on marvin before ANALYZE
**********************************
cert=# explain analyze
cert-# select 'TO_TRANS (SUPRA) '::text, sum(cnt_t) as cnt_t,
sum(certrans_amount_t) as certrans_amount_t, sum(cnt_f) as cnt_f,
sum(certrans_amount_f) as certrans_amount_f from (select count(*) as
cnt_t, sum(certrans_amount) as certrans_amount_t, 0::int as cnt_f,
0::numeric as certrans_amount_f from certrans where certrans_active =
't' and certrans_date between '2004-09-12' and '2004-09-17 15:10' UNION
ALL select 0::int as cnt_t, 0::numeric as certrans_amount_t, count(*) as
cnt_f, sum(certrans_amount) as certrans_amount_f from certrans where
certrans_active = 'f' and certrans_date between '2004-09-12' and
'2004-09-17 15:10') as list;
QUERYPLAN
 
-----------------------------------------------------------------------
-----------------------------------------------------------------------
-------------------------------------------------Aggregate  (cost=9.01..9.01 rows=1 width=11) (actual
time=3172.67..3172.68 rows=1 loops=1)  ->  Subquery Scan list  (cost=4.49..8.99 rows=2 width=11) (actual
time=2626.05..3172.63 rows=2 loops=1)        ->  Append  (cost=4.49..8.99 rows=2 width=11) (actual
time=2626.04..3172.61 rows=2 loops=1)              ->  Subquery Scan "*SELECT* 1"  (cost=4.49..4.49 rows=1
width=11) (actual time=2626.04..2626.04 rows=1 loops=1)                    ->  Aggregate  (cost=4.49..4.49 rows=1
width=11)
(actual time=2626.02..2626.02 rows=1 loops=1)                          ->  Index Scan using certrans_certrans_date
on certrans  (cost=0.00..4.49 rows=1 width=11) (actual
time=0.37..1944.16 rows=329162 loops=1)                                Index Cond: ((certrans_date >=
'2004-09-12 00:00:00-04'::timestamp with time zone) AND (certrans_date
<= '2004-09-17 15:10:00-04'::timestamp with time zone))                                Filter: (certrans_active = true)
            ->  Subquery Scan "*SELECT* 2"  (cost=4.49..4.49 rows=1
 
width=11) (actual time=546.56..546.56 rows=1 loops=1)                    ->  Aggregate  (cost=4.49..4.49 rows=1
width=11)
(actual time=546.54..546.54 rows=1 loops=1)                          ->  Index Scan using certrans_certrans_date
on certrans  (cost=0.00..4.49 rows=1 width=11) (actual time=0.42..543.94
rows=1061 loops=1)                                Index Cond: ((certrans_date >=
'2004-09-12 00:00:00-04'::timestamp with time zone) AND (certrans_date
<= '2004-09-17 15:10:00-04'::timestamp with time zone))                                Filter: (certrans_active =
false)Totalruntime: 3173.07 msec
 
(14 rows)

******************* on romeo before ANALYZE
**********************************
cert=# explain analyze
cert-# select 'TO_TRANS (SUPRA) '::text, sum(cnt_t) as cnt_t,
sum(certrans_amount_t) as certrans_amount_t, sum(cnt_f) as cnt_f,
sum(certrans_amount_f) as certrans_amount_f from (select count(*) as
cnt_t, sum(certrans_amount) as certrans_amount_t, 0::int as cnt_f,
0::numeric as certrans_amount_f from certrans where certrans_active =
't' and certrans_date between '2004-09-12' and '2004-09-17 15:10' UNION
ALL select 0::int as cnt_t, 0::numeric as certrans_amount_t, count(*) as
cnt_f, sum(certrans_amount) as certrans_amount_f from certrans where
certrans_active = 'f' and certrans_date between '2004-09-12' and
'2004-09-17 15:10') as list;
QUERY
PLAN
-----------------------------------------------------------------------
-----------------------------------------------------------------------
-------------------------------------------------Aggregate  (cost=601160.96..601160.96 rows=1 width=80) (actual
time=214478.840..214478.841 rows=1 loops=1)  ->  Subquery Scan list  (cost=407872.85..601160.93 rows=2 width=80)
(actual time=7306.212..214478.553 rows=2 loops=1)        ->  Append  (cost=407872.85..601160.91 rows=2 width=10)
(actual
time=7306.198..214478.531 rows=2 loops=1)              ->  Subquery Scan "*SELECT* 1" (cost=407872.85..407872.86
rows=1 width=10) (actual time=7306.195..7306.199 rows=1 loops=1)                    ->  Aggregate
(cost=407872.85..407872.85rows=1
 
width=10) (actual time=7306.181..7306.182 rows=1 loops=1)                          ->  Index Scan using
certrans_certrans_date
on certrans  (cost=0.00..406617.92 rows=250986 width=10) (actual
time=16.278..6442.917 rows=329162 loops=1)                                Index Cond: ((certrans_date >=
'2004-09-12 00:00:00-04'::timestamp with time zone) AND (certrans_date
<= '2004-09-17 15:10:00-04'::timestamp with time zone))                                Filter: (certrans_active = true)
->
Subquery Scan "*SELECT* 2"  (cost=193288.04..193288.05 rows=1 width=10)
(actual time=207172.320..207172.323 rows=1 loops=1)                    ->  Aggregate  (cost=193288.04..193288.04
rows=1
width=10) (actual time=207172.293..207172.294 rows=1 loops=1)                          ->  Index Scan using
certrans_certrans_active
on certrans  (cost=0.00..193271.08 rows=3392 width=10) (actual
time=1.209..207169.751 rows=1061 loops=1)                                Index Cond: (certrans_active = false)
                     Filter: ((certrans_date >= '2004-09-12
 
00:00:00-04'::timestamp with time zone) AND (certrans_date <=
'2004-09-17 15:10:00-04'::timestamp with time zone))Total runtime: 214479.023 ms
(14 rows)

******************* on marvin after ANALYZE
**********************************
cert=# vacuum analyze certrans;
VACUUM
cert=# explain
cert-# select 'TO_TRANS (SUPRA) '::text, sum(cnt_t) as cnt_t,
sum(certrans_amount_t) as certrans_amount_t, sum(cnt_f) ascnt_f,
sum(certrans_amount_f) as certrans_amount_f from (select count(*) as
cnt_t, sum(certrans_amount) as certrans_amount_t, 0::int as cnt_f,
0::numeric as certrans_amount_f from certrans where certrans_active =
't' and certrans_date between '2004-09-12' and '2004-09-17 15:10' UNION
ALL select 0::int as cnt_t, 0::numeric as certrans_amount_t, count(*) as
cnt_f, sum(certrans_amount) as certrans_amount_f from certrans where
certrans_active = 'f' and certrans_date between '2004-09-12' and
'2004-09-17 15:10') as list;
QUERYPLAN
 
-----------------------------------------------------------------------
-----------------------------------------------------------------------
-------------------------------------------------Aggregate  (cost=639660.78..639660.78 rows=1 width=11)  ->  Subquery
Scanlist  (cost=424765.55..639660.76 rows=2 width=11)        ->  Append  (cost=424765.55..639660.76 rows=2 width=11)
         ->  Subquery Scan "*SELECT* 1" (cost=424765.55..424765.55
 
rows=1 width=11)                    ->  Aggregate  (cost=424765.55..424765.55 rows=1
width=11)                          ->  Index Scan using certrans_certrans_date
on certrans  (cost=0.00..423625.93 rows=227924 width=11)                                Index Cond: ((certrans_date >=
'2004-09-12 00:00:00-04'::timestamp with time zone) AND (certrans_date
<= '2004-09-17 15:10:00-04'::timestamp with time zone))                                Filter: (certrans_active = true)
            ->  Subquery Scan "*SELECT* 2" (cost=214895.21..214895.21
 
rows=1 width=11)                    ->  Aggregate  (cost=214895.21..214895.21 rows=1
width=11)                          ->  Index Scan using certrans_certrans_active
on certrans  (cost=0.00..214880.98 rows=2846 width=11)                                Index Cond: (certrans_active =
false)                               Filter: ((certrans_date >= '2004-09-12
 
00:00:00-04'::timestamp with time zone) AND (certrans_date <=
'2004-09-17 15:10:00-04'::timestamp with time zone))
(13 rows)

******************* on romeo after ANALYZE
**********************************
cert=# vacuum analyze certrans;
VACUUM
cert=# explain
cert-# select 'TO_TRANS (SUPRA) '::text, sum(cnt_t) as cnt_t,
sum(certrans_amount_t) as certrans_amount_t, sum(cnt_f) as cnt_f,
sum(certrans_amount_f) as certrans_amount_f from (select count(*) as
cnt_t, sum(certrans_amount) as certrans_amount_t, 0::int as cnt_f,
0::numeric as certrans_amount_f from certrans where certrans_active =
't' and certrans_date between '2004-09-16' and '2004-09-17 15:10' UNION
ALL select 0::int as cnt_t, 0::numeric as certrans_amount_t, count(*) as
cnt_f, sum(certrans_amount) as certrans_amount_f from certrans where
certrans_active = 'f' and certrans_date between '2004-09-16' and
'2004-09-17 15:10') as list;
QUERYPLAN
 
-----------------------------------------------------------------------
-----------------------------------------------------------------------
-------------------------------------------------Aggregate  (cost=198145.87..198145.87 rows=1 width=80)  ->  Subquery
Scanlist  (cost=116922.43..198145.84 rows=2 width=80)        ->  Append  (cost=116922.43..198145.82 rows=2 width=10)
         ->  Subquery Scan "*SELECT* 1" (cost=116922.43..116922.44
 
rows=1 width=10)                    ->  Aggregate  (cost=116922.43..116922.43 rows=1
width=10)                          ->  Index Scan using certrans_certrans_date
on certrans  (cost=0.00..116556.16 rows=73254 width=10)                                Index Cond: ((certrans_date >=
'2004-09-16 00:00:00-04'::timestamp with time zone) AND (certrans_date
<= '2004-09-17 15:10:00-04'::timestamp with time zone))                                Filter: (certrans_active = true)
            ->  Subquery Scan "*SELECT* 2"  (cost=81223.37..81223.38
 
rows=1 width=10)                    ->  Aggregate  (cost=81223.37..81223.37 rows=1
width=10)                          ->  Index Scan using certrans_certrans_active
on certrans  (cost=0.00..81219.41 rows=790 width=10)                                Index Cond: (certrans_active =
false)                               Filter: ((certrans_date >= '2004-09-16
 
00:00:00-04'::timestamp with time zone) AND (certrans_date <=
'2004-09-17 15:10:00-04'::timestamp with time zone))
(13 rows)

After I ran "vacuum analyze" or "analyze" things got worse on marvin and
it did not get better with pg_autovacuum help.

Is there any way to find out what's going on?

-- 
D'Arcy J.M. Cain <darcy@druid.net>         |  Democracy is three wolves
http://www.druid.net/darcy/                |  and a sheep voting on
+1 416 425 1212     (DoD#0082)    (eNTP)   |  what's for dinner.

"D'Arcy J.M. Cain" <darcy@druid.net> writes:
> I had previously mentioned that queries run much different depending on
> whether a VACUUM ANALYZE is done or just a plain ANALYZE.

The problem appears to be that it's picking the wrong index to use for
the second part of the query (the certrans_active = 'f' part).  You have
not shown us enough info to guess why though.
        regards, tom lane

On Tue, 21 Sep 2004 11:00:33 -0400
Tom Lane <tgl@sss.pgh.pa.us> wrote:
> "D'Arcy J.M. Cain" <darcy@druid.net> writes:
> > I had previously mentioned that queries run much different depending
> > on whether a VACUUM ANALYZE is done or just a plain ANALYZE.
> 
> The problem appears to be that it's picking the wrong index to use for
> the second part of the query (the certrans_active = 'f' part).  You
> have not shown us enough info to guess why though.

Well, I guess I am looking for is hints on what other information you
might need.  The problem is that both of these versions are running the
same schema, the same data and the same indexes.  In fact, we are
running software to keep both databases in sync.

As it turns out, if we VACUUM ANALYZE or ANALYZE the 7.3 database we
lose the quick access that we had seen.  We never get back to 9 again. 
I am not sure what that means.  It could have been a false reading
except that we definitely say a better result when it was 9.

If it helps, here is the table definition.  There are also a bunch of
rules on insert, update and delete but I don't imagine those have any
effect on selects.  Is there anything else I can give you?
                             Table "public.certrans"      Column        |            Type             |            
Modifiers
---------------------+-----------------------------+-------------------
-------certrans_id         | integer                     | not nullcertrans_active     | boolean                     |
defaulttruecertificate_id      | integer                     | not nullcertype_id          | character varying(1)
| not nullcertrans_date       | timestamp(0) with time zone | not null default
 
('now'::text)::timestamp(6) with time zonecertrans_amount     | numeric(14,2)               | not nullstuser_id
 | integer                     | not nulloperator_id         | integer                     | not nullcertrans_ref
| text                        | cash_out_id         | integer                     | certrans_void_ref   | integer
             | certrans_local_date | date                        | default
 
('now'::text)::datecertrans_local_time | time without time zone      | default
('now'::text)::time(6) with time zonechannel_id          | integer                     | default 0loyalty_amount      |
numeric(14,2)              | default 0
 
Indexes:   "certrans_pkey" primary key, btree (certrans_id)   "certrans_cash_out_id" btree (cash_out_id)
"certrans_certificate_id"btree (certificate_id)   "certrans_certrans_active" btree (certrans_active)
"certrans_certrans_date"btree (certrans_date)   "certrans_certrans_local_date" btree (certrans_local_date)
"certrans_certrans_void_ref"btree (certrans_void_ref)   "certrans_certype_id" btree (certype_id)
"certrans_channel_id"btree (channel_id)   "certrans_oid" btree (oid)   "certrans_operator_id" btree (operator_id)
"certrans_sortkey"btree (certificate_id, certrans_id)   "certrans_stuser_id" btree (stuser_id)
 
Foreign-key constraints:   "$1" FOREIGN KEY (certificate_id) REFERENCES
certificate(certificate_id)


-- 
D'Arcy J.M. Cain <darcy@druid.net>         |  Democracy is three wolves
http://www.druid.net/darcy/                |  and a sheep voting on
+1 416 425 1212     (DoD#0082)    (eNTP)   |  what's for dinner.