Re: Query is taking 5 HOURS to Complete on 8.1 version

Hello all,

I've made the changes to view to use UNION ALL and the where NOT IN
suggestions...the query now takes a little under 3 hours instead of 5 --
here is 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)

smiley2211 wrote:
>
> This query is taking less than 5 minutes on 7.4 but over 5 hours on 8.1...
>
> PostgreSQL 8.1.4 on x86_64-unknown-linux-gnu, compiled by GCC gcc (GCC)
> 4.1.0 (SUSE Linux)
> Total runtime: 20448310.101 ms = 5.6800862 hour
> (132 rows)
>
> --postgresql.conf:
>
> shared_buffers = 114688 # min 16 or max_connections*2, 8KB
> each
> #temp_buffers = 20000 # min 100, 8KB each
> #max_prepared_transactions = 5 # can be 0 or more
> # note: increasing max_prepared_transactions costs ~600 bytes of shared
> memory
> # per transaction slot, plus lock space (see max_locks_per_transaction).
> work_mem = 10240 # size in KB
> maintenance_work_mem = 64384 # min 1024, size in KB
> max_stack_depth = 4096 # min 100, size in KB
>
> # - Free Space Map -
>
> max_fsm_pages = 500000 # min max_fsm_relations*16, 6 bytes each
> max_fsm_relations = 1000 # min 100, ~70 bytes each
>
> # - Kernel Resource Usage -
>
> #max_files_per_process = 1000 # min 25
> #preload_libraries = ''
>
> # - Cost-Based Vacuum Delay -
>
> #vacuum_cost_delay = 0 # 0-1000 milliseconds
> #vacuum_cost_page_hit = 1 # 0-10000 credits
> #vacuum_cost_page_miss = 10 # 0-10000 credits
> #vacuum_cost_page_dirty = 20 # 0-10000 credits
> #vacuum_cost_limit = 200 # 0-10000 credits
>
> # - Background writer -
>
> #bgwriter_delay = 200 # 10-10000 milliseconds between
> rounds
> #bgwriter_lru_percent = 1.0 # 0-100% of LRU buffers
> scanned/round
> #bgwriter_lru_maxpages = 5 # 0-1000 buffers max written/round
> #bgwriter_all_percent = 0.333 # 0-100% of all buffers
> scanned/round
> #bgwriter_all_maxpages = 5 # 0-1000 buffers max written/round
>
>
> #---------------------------------------------------------------------------
> # WRITE AHEAD LOG
> #---------------------------------------------------------------------------
>
> # - Settings -
>
> #fsync = on # turns forced synchronization on
> or off
> #wal_sync_method = fsync # the default is the first option
> # supported by the operating
> system:
> # open_datasync
> # fdatasync
> # fsync
> # fsync_writethrough
> # open_sync
> #full_page_writes = on # recover from partial page writes
> #wal_buffers = 8 # min 4, 8KB each
> #commit_delay = 0 # range 0-100000, in microseconds
> #commit_siblings = 5 # range 1-1000
>
> # - Checkpoints -
>
> checkpoint_segments = 12 # in logfile segments, min 1, 16MB
> each
> #checkpoint_timeout = 300 # range 30-3600, in seconds
> #checkpoint_warning = 30 # in seconds, 0 is off
>
> # - Archiving -
>
> #archive_command = '' # command to use to archive a
> logfile
> # segment
>
>
> #---------------------------------------------------------------------------
> # QUERY TUNING
> #---------------------------------------------------------------------------
>
> # - Planner Method Configuration -
>
> enable_bitmapscan = off
> enable_hashagg = on
> enable_hashjoin = on
> enable_indexscan = on
> enable_mergejoin = on
> enable_nestloop = on
> enable_seqscan = off
> enable_sort = on
> enable_tidscan = on
>
> # - Planner Cost Constants -
>
> effective_cache_size = 10000 # typically 8KB each
> random_page_cost = 4 # units are one sequential page
> fetch
> # cost
> #cpu_tuple_cost = 0.01 # (same)
> #cpu_index_tuple_cost = 0.001 # (same)
> #cpu_operator_cost = 0.0025 # (same)
> #---------------------------------------------------------------------------
> # LOCK MANAGEMENT
> #---------------------------------------------------------------------------
>
> #deadlock_timeout = 1000 # in milliseconds
> #max_locks_per_transaction = 64 # min 10
> # note: each lock table slot uses ~220 bytes of shared memory, and there
> are
> # max_locks_per_transaction * (max_connections +
> max_prepared_transactions)
> # lock table slots.
>
>

--
View this message in context: http://www.nabble.com/Query-is-taking-5-HOURS-to-Complete-on-8.1-version-tf4019778.html#a11451397
Sent from the PostgreSQL - performance mailing list archive at Nabble.com.