Re: Upgraded from 7.4 to 8.1.4 QUERIES NOW SLOW!!!

I suffered the same fate when upgrading some time back.  The single biggest
issue for me was that the default 8.X setup changed what had been fast query
plans using indexes to slow plans using sequential scans.  Changing the
random_page_cost in postgresql.conf from 4.0 to 2.0 (which indicates to
Postgres that reading index pages isn't such a big deal, encouraging index
use) solved most of these issues for me.

Jeff

-----Original Message-----
From: smiley2211 [mailto:smiley2211@yahoo.com]
Sent: Friday, September 21, 2007 8:14 AM
To: pgsql-performance@postgresql.org
Subject: Re: [PERFORM] Upgraded from 7.4 to 8.1.4 QUERIES NOW SLOW!!!



Dennis,

Thanks for your reply.

No, the OLD server are no longer available (decommissioned) - the new
servers are definitely better h\w.

I do not have any queries to EXPLAIN ANALYZE as they are built by the
application and I am not allowed to enable logging on for that server - so
where do I go from here???

I am pretty much trying to make changes in the postgresql.conf file but
don't have a CLUE as to what starting numbers I should be looking at to
change(???)

Here is the EXPLAIN ANALYZE for the ONE (1) query I do have...it takes 4 - 5
hours to run a SELECT with the 'EXPLAIN ANALYZE':



QUERY PLAN


----------------------------------------------------------------------------
----------------------------------------------------------------------------
----------------------------------------------------------------------------
-
-------------------
 Limit  (cost=100013612.76..299939413.70 rows=1 width=8) (actual
time=10084289.859..10084289.861 rows=1 loops=1)
   ->  Subquery Scan people_consent  (cost=100013612.76..624068438343.99
rows=3121 width=8) (actual time=10084289.853..10084289.853 rows=1 loops=1)
         ->  Append  (cost=100013612.76..624068438312.78 rows=3121
width=815) (actual time=10084289.849..10084289.849 rows=1 loops=1)
               ->  Nested Loop  (cost=100013612.76..100013621.50 rows=2
width=815) (actual time=10084289.846..10084289.846 rows=1 loops=1)
                     ->  Unique  (cost=100013612.76..100013612.77 rows=2
width=8) (actual time=10084289.817..10084289.817 rows=1 loops=1)
                           ->  Sort  (cost=100013612.76..100013612.77 rows=2
width=8) (actual time=10084289.814..10084289.814 rows=1 loops=1)
                                 Sort Key: temp_consent.id
                                 ->  Unique
(cost=100013612.71..100013612.73 rows=2 width=36) (actual
time=10084245.195..10084277.468 rows=7292 loops=1)
                                       ->  Sort
(cost=100013612.71..100013612.72 rows=2 width=36) (actual
time=10084245.191..10084254.425 rows=7292 loops=1)
                                             Sort Key: id, daterecorded,
answer
                                             ->  Append
(cost=100013515.80..100013612.70 rows=2 width=36) (actual
time=10083991.226..10084228.613 rows=7292 loops=1)
                                                   ->  HashAggregate
(cost=100013515.80..100013515.82 rows=1 width=36) (actual
time=10083991.223..10083998.046 rows=3666 loops=1)
                                                         ->  Nested Loop
(cost=100000060.61..100013515.80 rows=1 width=36) (actual
time=388.263..10083961.330 rows=3702 loops=1)
                                                               ->  Nested
Loop  (cost=100000060.61..100013511.43 rows=1 width=36) (actual
time=388.237..10083897.268 rows=3702 loops=1)
                                                                     ->
Nested Loop  (cost=100000060.61..100013507.59 rows=1 width=24) (actual
time=388.209..10083833.870 rows=3702 loops=1)

->  Nested Loop  (cost=100000060.61..100013504.56 rows=1 width=24)
-> (actual
time=388.173..10083731.122 rows=3702 loops=1)


Join Filter: ("inner".question_answer_id = "outer".id)


->  Nested Loop  (cost=60.61..86.33 rows=1 width=28) (actual
time=13.978..114.768 rows=7430 loops=1)


->  Index Scan using answers_answer_un on answers a  (cost=0.00..5.01
-> rows=1
width=28) (actual time=0.084..0.088 rows=1 loops=1)


Index Cond: ((answer)::text = 'Yes'::text)


->  Bitmap Heap Scan on questions_answers qa  (cost=60.61..81.23 rows=7
width=16) (actual time=13.881..87.112 rows=7430 loops=1)


Recheck Cond: ((qa.answer_id = "outer".id) AND (((qa.question_tag)::text =
'consentTransfer'::text) OR ((qa.question_tag)::text = 'share
WithEval'::text)))


->  BitmapAnd  (cost=60.61..60.61 rows=7 width=0) (actual
time=13.198..13.198 rows=0 loops=1)


->  Bitmap Index Scan on qs_as_answer_id  (cost=0.00..5.27 rows=649
-> width=0)
(actual time=9.689..9.689 rows=57804 loops=1)


Index Cond: (qa.answer_id = "outer".id)


->  BitmapOr  (cost=55.08..55.08 rows=6596 width=0) (actual
time=2.563..2.563 rows=0 loops=1)


->  Bitmap Index Scan on qs_as_qtag  (cost=0.00..27.54 rows=3298
-> width=0)
(actual time=1.923..1.923 rows=6237 loops=1)


Index Cond: ((question_tag)::text = 'consentTransfer'::text)


->  Bitmap Index Scan on qs_as_qtag  (cost=0.00..27.54 rows=3298
-> width=0)
(actual time=0.634..0.634 rows=2047 loops=1)


Index Cond: ((question_tag)::text = 'shareWithEval'::text)


->  Seq Scan on encounters_questions_answers eqa
(cost=100000000.00..100007608.66 rows=464766 width=8) (actual
time=0.003..735.934 rows=464766 loop
s=7430)

->  Index Scan using encounters_id on encounters ec  (cost=0.00..3.02
-> rows=1
width=8) (actual time=0.016..0.018 rows=1 loops=3702)


Index Cond: (ec.id = "outer".encounter_id)
                                                                     ->
Index Scan using enrollements_pk on enrollments en  (cost=0.00..3.82 rows=1
width=20) (actual time=0.008..0.010 rows=1 loops=3702)

Index Cond: ("outer".enrollment_id = en.id)
                                                               ->  Index
Scan using people_pk on people p  (cost=0.00..4.35 rows=1 width=8) (actual
time=0.008..0.010 rows=1 loops=3702)
                                                                     Index
Cond: (p.id = "outer".person_id)
                                                   ->  HashAggregate
(cost=96.86..96.87 rows=1 width=36) (actual time=205.471..212.207 rows=3626
loops=1)
                                                         ->  Nested Loop
(cost=60.61..96.85 rows=1 width=36) (actual time=13.163..196.421 rows=3722
loops=1)
                                                               ->  Nested
Loop  (cost=60.61..92.48 rows=1 width=36) (actual time=13.149..158.112
rows=3722 loops=1)
                                                                     ->
Nested Loop  (cost=60.61..89.36 rows=1 width=24) (actual
time=13.125..120.021 rows=3722 loops=1)

->  Nested Loop  (cost=60.61..86.33 rows=1 width=28) (actual
time=13.013..48.460 rows=7430 loops=1)


->  Index Scan using answers_answer_un on answers a  (cost=0.00..5.01
-> rows=1
width=28) (actual time=0.030..0.032 rows=1 loops=1)


Index Cond: ((answer)::text = 'Yes'::text)


->  Bitmap Heap Scan on questions_answers qa  (cost=60.61..81.23 rows=7
width=16) (actual time=12.965..28.902 rows=7430 loops=1)


Recheck Cond: ((qa.answer_id = "outer".id) AND (((qa.question_tag)::text =
'consentTransfer'::text) OR ((qa.question_tag)::text = 'shareWithEv
al'::text)))


->  BitmapAnd  (cost=60.61..60.61 rows=7 width=0) (actual
time=12.288..12.288 rows=0 loops=1)


->  Bitmap Index Scan on qs_as_answer_id  (cost=0.00..5.27 rows=649
-> width=0)
(actual time=8.985..8.985 rows=57804 loops=1)


Index Cond: (qa.answer_id = "outer".id)


->  BitmapOr  (cost=55.08..55.08 rows=6596 width=0) (actual
time=2.344..2.344 rows=0 loops=1)


->  Bitmap Index Scan on qs_as_qtag  (cost=0.00..27.54 rows=3298
-> width=0)
(actual time=1.762..1.762 rows=6237 loops=1)


Index Cond: ((question_tag)::text = 'consentTransfer'::text)


->  Bitmap Index Scan on qs_as_qtag  (cost=0.00..27.54 rows=3298
-> width=0)
(actual time=0.578..0.578 rows=2047 loops=1)


Index Cond: ((question_tag)::text = 'shareWithEval'::text)

->  Index Scan using ctccalls_qs_as_qaid on ctccalls_questions_answers
-> cqa
(cost=0.00..3.02 rows=1 width=8) (actual time=0.005..0.006 rows=1
loops=7430)


Index Cond: (cqa.question_answer_id = "outer".id)
                                                                     ->
Index Scan using ctccalls_pk on ctccalls c  (cost=0.00..3.11 rows=1
width=20) (actual time=0.003..0.005 rows=1 loops=3722)

Index Cond: (c.id = "outer".call_id)
                                                               ->  Index
Scan using people_pk on people p  (cost=0.00..4.35 rows=1 width=8) (actual
time=0.004..0.005 rows=1 loops=3722)
                                                                     Index
Cond: (p.id = "outer".person_id)
                     ->  Index Scan using people_pk on people
(cost=0.00..4.35 rows=1 width=815) (actual time=0.018..0.018 rows=1 loops=1)
                           Index Cond: (people.id = "outer".id)
               ->  Subquery Scan "*SELECT* 2"
(cost=100000000.00..623968424691.25 rows=3119 width=676) (never executed)
                     ->  Seq Scan on people
(cost=100000000.00..623968424660.06 rows=3119 width=676) (never executed)
                           Filter: (NOT (subplan))
                           SubPlan
                             ->  Subquery Scan temp_consent
(cost=100010968.94..100010968.98 rows=2 width=8) (never executed) lines
1-69/129 56%


Index Cond: (cqa.question_answer_id = "outer".id)
                                                                     ->
Index Scan using ctccalls_pk on ctccalls c  (cost=0.00..3.11 rows=1
width=20) (actual time=0.003..0.005 rows=1 loops=3722)

Index Cond: (c.id = "outer".call_id)
                                                               ->  Index
Scan using people_pk on people p  (cost=0.00..4.35 rows=1 width=8) (actual
time=0.004..0.005 rows=1 loops=3722)
                                                                     Index
Cond: (p.id = "outer".person_id)
                     ->  Index Scan using people_pk on people
(cost=0.00..4.35 rows=1 width=815) (actual time=0.018..0.018 rows=1 loops=1)
                           Index Cond: (people.id = "outer".id)
               ->  Subquery Scan "*SELECT* 2"
(cost=100000000.00..623968424691.25 rows=3119 width=676) (never executed)
                     ->  Seq Scan on people
(cost=100000000.00..623968424660.06 rows=3119 width=676) (never executed)
                           Filter: (NOT (subplan))
                           SubPlan
                             ->  Subquery Scan temp_consent
(cost=100010968.94..100010968.98 rows=2 width=8) (never executed)
                                   ->  Unique
(cost=100010968.94..100010968.96 rows=2 width=36) (never executed)
                                         ->  Sort
(cost=100010968.94..100010968.95 rows=2 width=36) (never executed)
                                               Sort Key: id, daterecorded,
answer
                                               ->  Append
(cost=100010872.03..100010968.93 rows=2 width=36) (never executed)
                                                     ->  HashAggregate
(cost=100010872.03..100010872.04 rows=1 width=36) (never executed)
                                                           ->  Nested Loop
(cost=100000907.99..100010872.02 rows=1 width=36) (never executed)
                                                                 Join
Filter: ("inner".question_answer_id = "outer".id)
                                                                 ->  Nested
Loop  (cost=60.61..90.69 rows=1 width=36) (never executed)
                                                                       ->
Nested Loop  (cost=0.00..9.37 rows=1 width=36) (never executed)

->  Index Scan using people_pk on people p  (cost=0.00..4.35 rows=1
-> width=8)
(never executed)


Index Cond: (id = $0)

->  Index Scan using answers_answer_un on answers a  (cost=0.00..5.01
-> rows=1
width=28) (never executed)


Index Cond: ((answer)::text = 'Yes'::text)
                                                                       ->
Bitmap Heap Scan on questions_answers qa  (cost=60.61..81.23 rows=7
width=16) (never executed)

Recheck Cond: ((qa.answer_id = "outer".id) AND (((qa.question_tag)::text =
'consentTransfer'::text) OR ((qa.question_tag)::text =
'shareWithEval'::text)
))

->  BitmapAnd  (cost=60.61..60.61 rows=7 width=0) (never executed)


->  Bitmap Index Scan on qs_as_answer_id  (cost=0.00..5.27 rows=649
-> width=0)
(never executed)


Index Cond: (qa.answer_id = "outer".id)


->  BitmapOr  (cost=55.08..55.08 rows=6596 width=0) (never executed)


->  Bitmap Index Scan on qs_as_qtag  (cost=0.00..27.54 rows=3298
-> width=0)
(never executed)


Index Cond: ((question_tag)::text = 'consentTransfer'::text)


->  Bitmap Index Scan on qs_as_qtag  (cost=0.00..27.54 rows=3298
-> width=0)
(never executed)


Index Cond: ((question_tag)::text = 'shareWithEval'::text)
                                                                 ->  Hash
Join  (cost=100000847.38..100010780.52 rows=65 width=20) (never executed)
                                                                       Hash
Cond: ("outer".encounter_id = "inner".id)
                                                                       ->
Seq Scan on encounters_questions_answers eqa
(cost=100000000.00..100007608.66 rows=464766 width=8) (never executed)
                                                                       ->
Hash  (cost=847.37..847.37 rows=3 width=20) (never executed)

->  Hash Join  (cost=214.73..847.37 rows=3 width=20) (never executed)


Hash Cond: ("outer".enrollment_id = "inner".id)


->  Index Scan using encounters_id on encounters ec  (cost=0.00..524.72
rows=21578 width=8) (never executed)


->  Hash  (cost=214.73..214.73 rows=1 width=20) (never executed)


->  Index Scan using enrollements_pk on enrollments en
-> (cost=0.00..214.73
rows=1 width=20) (never executed)


Filter: ($0 = person_id)
                                                     ->  HashAggregate
(cost=96.86..96.87 rows=1 width=36) (never executed)
                                                           ->  Nested Loop
(cost=60.61..96.85 rows=1 width=36) (never executed)
                                                                 ->  Nested
Loop  (cost=60.61..93.72 rows=1 width=32) (never executed)
                                                                       ->
Nested Loop  (cost=60.61..90.69 rows=1 width=36) (never executed)

->  Nested Loop  (cost=0.00..9.37 rows=1 width=36) (never executed)


->  Index Scan using people_pk on people p  (cost=0.00..4.35 rows=1
-> width=8)
(never executed)


Index Cond: (id = $0)


->  Index Scan using answers_answer_un on answers a  (cost=0.00..5.01
-> rows=1
width=28) (never executed)


Index Cond: ((answer)::text = 'Yes'::text)

->  Bitmap Heap Scan on questions_answers qa  (cost=60.61..81.23 rows=7
width=16) (never executed)


Recheck Cond: ((qa.answer_id = "outer".id) AND (((qa.question_tag)::text =
'consentTransfer'::text) OR ((qa.question_tag)::text = 'shareWithEval':
:text)))


->  BitmapAnd  (cost=60.61..60.61 rows=7 width=0) (never executed)


->  Bitmap Index Scan on qs_as_answer_id  (cost=0.00..5.27 rows=649
-> width=0)
(never executed)


Index Cond: (qa.answer_id = "outer".id)


->  BitmapOr  (cost=55.08..55.08 rows=6596 width=0) (never executed)


->  Bitmap Index Scan on qs_as_qtag  (cost=0.00..27.54 rows=3298
-> width=0)
(never executed)


Index Cond: ((question_tag)::text = 'consentTransfer'::text)


->  Bitmap Index Scan on qs_as_qtag  (cost=0.00..27.54 rows=3298
-> width=0)
(never executed)


Index Cond: ((question_tag)::text = 'shareWithEval'::text)
                                                                       ->
Index Scan using ctccalls_qs_as_qaid on ctccalls_questions_answers cqa
(cost=0.00..3.02 rows=1 width=8) (never executed)

Index Cond: (cqa.question_answer_id = "outer".id)
                                                                 ->  Index
Scan using ctccalls_pk on ctccalls c  (cost=0.00..3.11 rows=1 width=20)
(never executed)
                                                                       Index
Cond: (c.id = "outer".call_id)

Filter: ($0 = person_id)
 Total runtime: 10084292.497 ms
(125 rows)


Thanks...Marsha

--
View this message in context:
http://www.nabble.com/Upgraded-from-7.4-to-8.1.4-QUERIES-NOW-SLOW%21%21%21-t
f4489502.html#a12820410
Sent from the PostgreSQL - performance mailing list archive at Nabble.com.


---------------------------(end of broadcast)---------------------------
TIP 3: Have you checked our extensive FAQ?

               http://www.postgresql.org/docs/faq