Re: difference in query plan when db is restored

Finally... issue is resolved :) Increased the DST to 10K and ran ANALYZE
on the db again.

QUERY PLAN

------------------------------------------------------------------------
------------------------------------------------------------------------
------------------
Sort (cost=7561.71..7562.23 rows=208 width=373) (actual
time=43.663..43.899 rows=3445 loops=1)
Sort Key: tblappliccomp.idnumber2, tblappliccomp.idnumber
Sort Method: quicksort Memory: 1045kB
-> Hash Left Join (cost=1006.54..7553.70 rows=208 width=373)
(actual time=4.915..38.416 rows=3445 loops=1)
Hash Cond: (tblappliccomp.usercrid = tbluser.idnumber)
-> Nested Loop Left Join (cost=980.52..3337.69 rows=208
width=378) (actual time=4.651..17.277 rows=3445 loops=1)
-> Bitmap Heap Scan on tblappliccomp
(cost=980.52..1816.60 rows=208 width=181) (actual time=4.641..6.405
rows=3445 loops=1)
Recheck Cond: ((applicid = 90000872) AND ("inout" =
1))
Filter: ((otherr IS NULL) OR (otherr = 0))
-> BitmapAnd (cost=980.52..980.52 rows=223
width=0) (actual time=4.608..4.608 rows=0 loops=1)
-> Bitmap Index Scan on
tblappliccompindapplicid (cost=0.00..67.00 rows=3555 width=0) (actual
time=0.335..0.335 rows=3555 loops=1)
Index Cond: (applicid = 90000872)
-> Bitmap Index Scan on
tblappliccompindinout (cost=0.00..913.16 rows=49177 width=0) (actual
time=4.246..4.246 rows=49177 loops=1)
Index Cond: ("inout" = 1)
-> Index Scan using tblcompanyindidnumber on tblcompany
(cost=0.00..7.30 rows=1 width=205) (actual time=0.002..0.002 rows=0
loops=3445)
Index Cond: (tblappliccomp.companyid = idnumber)
-> Hash (cost=21.01..21.01 rows=401 width=11) (actual
time=0.217..0.217 rows=401 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 19kB
-> Seq Scan on tbluser (cost=0.00..21.01 rows=401
width=11) (actual time=0.005..0.151 rows=401 loops=1)
SubPlan 1
-> Limit (cost=0.00..20.13 rows=1 width=15) (actual
time=0.005..0.005 rows=1 loops=3445)
-> Nested Loop Left Join (cost=0.00..20.13 rows=1
width=15) (actual time=0.005..0.005 rows=1 loops=3445)
-> Index Scan using leeindapplicid on lee
(cost=0.00..11.85 rows=1 width=8) (actual time=0.003..0.003 rows=1
loops=3445)
Index Cond: (applicid = 70058598)
Filter: ((eorg = tblappliccomp.companyid)
AND (eevent = tblappliccomp.confid))
-> Index Scan using tblreferralindidnumber on
tblreferral (cost=0.00..8.27 rows=1 width=23) (actual time=0.001..0.001
rows=1 loops=2947)
Index Cond: (lee.referralid = idnumber)
Total runtime: 44.260 ms
(28 rows)
-----Original Message-----
From: pgsql-general-owner(at)postgresql(dot)org
[mailto:pgsql-general-owner(at)postgresql(dot)org] On Behalf Of John Watts
Sent: 19 May 2012 14:04
To: Tom Lane
Cc: pgsql-general(at)postgresql(dot)org
Subject: Re: [GENERAL] difference in query plan when db is restored

Tom, thanks very much for your response.

I've run REINDEX on the db and ANALYZE multiple times - there is no
dramatic improvement.

I appreciate all the impressive effort and contribution of PostgreSQL
developers and am fully aware of importance of bug fixes. Please
acknowledge I am running into the exact same problem with version 9.1.2.
The query plan is again 33 rows and it takes 23992.996 ms to execute as
opposed to 21 rows and less than one second execution on the production
server.

Not sure what where to go from here...

QUERY PLAN

------------------------------------------------------------------------
------------------------------------------------------------------------
------------------
Sort (cost=7807.69..7808.19 rows=200 width=373) (actual
time=23992.283..23992.577 rows=3445 loops=1)
Sort Key: tblappliccomp.idnumber2, tblappliccomp.idnumber
Sort Method: quicksort Memory: 1045kB
-> Hash Left Join (cost=994.00..7800.05 rows=200 width=373) (actual
time=15.723..23983.602 rows=3445 loops=1)
Hash Cond: (tblappliccomp.usercrid = tbluser.idnumber)
-> Nested Loop Left Join (cost=967.98..3238.24 rows=200
width=378) (actual time=5.741..30.190 rows=3445 loops=1)
-> Bitmap Heap Scan on tblappliccomp
(cost=967.98..1771.49 rows=200 width=181) (actual time=5.730..10.220
rows=3445 loops=1)
Recheck Cond: ((applicid = 90000872) AND ("inout" =
1))
Filter: ((otherr IS NULL) OR (otherr = 0))
-> BitmapAnd (cost=967.98..967.98 rows=214
width=0) (actual time=5.689..5.689 rows=0 loops=1)
-> Bitmap Index Scan on
tblappliccompindapplicid (cost=0.00..66.27 rows=3458 width=0) (actual
time=0.460..0.460 rows=3555 loops=1)
Index Cond: (applicid = 90000872)
-> Bitmap Index Scan on
tblappliccompindinout (cost=0.00..901.36 rows=48670 width=0) (actual
time=5.201..5.201 rows=49177 loops=1)
Index Cond: ("inout" = 1)
-> Index Scan using tblcompanyindidnumber on tblcompany
(cost=0.00..7.32 rows=1 width=205) (actual time=0.004..0.004 rows=0
loops=3445)
Index Cond: (tblappliccomp.companyid = idnumber)
-> Hash (cost=21.01..21.01 rows=401 width=11) (actual
time=0.213..0.213 rows=401 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 19kB
-> Seq Scan on tbluser (cost=0.00..21.01 rows=401
width=11) (actual time=0.006..0.139 rows=401 loops=1)
SubPlan 1
-> Limit (cost=10.37..22.67 rows=1 width=15) (actual
time=6.950..6.950 rows=1 loops=3445)
-> Nested Loop Left Join (cost=10.37..22.67 rows=1
width=15) (actual time=6.949..6.949 rows=1 loops=3445)
-> Bitmap Heap Scan on lee (cost=10.37..14.39
rows=1 width=8) (actual time=6.942..6.942 rows=1 loops=3445)
Recheck Cond: ((applicid = 70058598) AND
(eevent = tblappliccomp.confid))
Filter: (eorg = tblappliccomp.companyid)
-> BitmapAnd (cost=10.37..10.37 rows=1
width=0) (actual time=6.936..6.936 rows=0 loops=3445)
-> Bitmap Index Scan on
leeindapplicid (cost=0.00..4.36 rows=3 width=0) (actual
time=0.007..0.007 rows=3 loops=3445)
Index Cond: (applicid =
70058598)
-> Bitmap Index Scan on leeindeevent
(cost=0.00..5.76 rows=189 width=0) (actual time=6.892..6.892 rows=85704
loops=3445)
Index Cond: (eevent =
tblappliccomp.confid)
-> Index Scan using tblreferralindidnumber on
tblreferral (cost=0.00..8.27 rows=1 width=23) (actual time=0.004..0.004
rows=1 loops=2947)
Index Cond: (lee.referralid = idnumber)
Total runtime: 23992.996 ms
(33 rows)

-----Original Message-----
From: Tom Lane [mailto:tgl(at)sss(dot)pgh(dot)pa(dot)us]
Sent: 18 May 2012 19:29
To: John Watts
Cc: pgsql-general(at)postgresql(dot)org
Subject: Re: [GENERAL] difference in query plan when db is restored

"John Watts" <jwatts(at)promotion-update(dot)com> writes:
> Anyone?

I'm still suspicious that you're not really re-ANALYZE'ing the relevant
tables, because there are some discrepancies in the row count estimates
that seem hard to explain otherwise, eg here:

-> Index Scan using tblcompanyindidnumber on tblcompany
(cost=0.00..8.40 rows=1 width=206) (actual time=0.003..0.003 rows=0
loops=3445)
Index Cond: (tblappliccomp.companyid =
tblcompany.idnumber)

vs

-> Bitmap Heap Scan on tblcompany (cost=13.07..1774.92
rows=620 width=185) (actual time=0.013..0.013 rows=0 loops=3445)
Recheck Cond: (tblappliccomp.companyid =
tblcompany.idnumber)
-> Bitmap Index Scan on tblcompanyindidnumber
(cost=0.00..12.91 rows=620 width=0) (actual time=0.011..0.011 rows=0
loops=3445)
Index Cond: (tblappliccomp.companyid =
tblcompany.idnumber)

That might be caused by missing stats for either tblcompany or
tblappliccomp. Or perhaps the problem is much different values of
default_statistics_target?

Also, I've got to say that this does not represent good practice:

> server_version | 8.3.0

You're missing eighteen minor-release updates on that server. We don't
do minor releases just to keep ourselves amused; there are a lot of
rather significant bug fixes that you're missing, possibly including
some that affect this issue.

regards, tom lane

--
Sent via pgsql-general mailing list (pgsql-general(at)postgresql(dot)org) To
make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general