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.