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

Query is taking 5 HOURS to Complete on 8.1 version

From
smiley2211
Date:
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#a11416966
Sent from the PostgreSQL - performance mailing list archive at Nabble.com.


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

From
Bill Moran
Date:
In response to smiley2211 <smiley2211@yahoo.com>:
>
> 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)

When was the last time you vacuum analyzed the database?

Also, you don't even provide the query.  I can't imagine how you'd expect
anyone to help you.  If vacuum analyze doesn't fix the problem, please
provide the query, explain output of the query, and the schema of any
tables involved, including information on indexes.

>
> --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.
>

--
Bill Moran
Collaborative Fusion Inc.
http://people.collaborativefusion.com/~wmoran/

wmoran@collaborativefusion.com
Phone: 412-422-3463x4023

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

From
smiley2211
Date:
Here is the EXPLAIN after I changed some conf file - now I am running another
EXPLAIN ANALYZE which may take 5 or more hours to complete :,(

effective_cache = 170000
enable_seqscan = on
enable _bitmapscan = on


 QUERY PLAN


--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
-
 Limit  (cost=27674.12..27674.21 rows=1 width=8)
   ->  Subquery Scan people_consent  (cost=27674.12..27978.41 rows=3121
width=8)
         ->  Unique  (cost=27674.12..27947.20 rows=3121 width=816)
               ->  Sort  (cost=27674.12..27681.92 rows=3121 width=816)
                     Sort Key: id, firstname, lastname, homephone,
workphone, al
tphone, eligibilityzipcode, address1, address2, city, state, zipcode1,
zipcode2,
 email, dayofbirth, monthofbirth, yearofbirth, ethnic_detail, external_id,
highe
stlevelofeducation_id, ethnicgroup_id, ethnicotherrace, entered_at,
entered_by,
besttimetoreach_id, language_id, otherlanguage, gender_id,
hispaniclatino_id, ca

nscheduleapt_id, mayweleaveamessage_id, ethnictribe, ethnicasian,
ethnicislander
                     ->  Append  (cost=13595.19..27492.98 rows=3121
width=816)
                           ->  Nested Loop  (cost=13595.19..13602.61 rows=2
widt
h=816)
                                 ->  Unique  (cost=13595.19..13595.20 rows=2
wid
th=8)
                                       ->  Sort  (cost=13595.19..13595.19
rows=2
 width=8)
                                             Sort Key: temp_consent2.id
                                             ->  Unique
(cost=13595.14..13595.1
6 rows=2 width=16)
                                                   ->  Sort
(cost=13595.14..135
95.15 rows=2 width=16)
                                                         Sort Key:
temp_consent.
daterecorded, temp_consent.id
                                                         ->  Subquery Scan
temp_
consent  (cost=13595.09..13595.13 rows=2 width=16)
                                                               ->  Unique
(cost
=13595.09..13595.11 rows=2 width=36)
                                                                     ->
Sort  (
cost=13595.09..13595.10 rows=2 width=36)

Sort
Key: id, daterecorded, answer


->  A
ppend  (cost=13506.81..13595.08 rows=2 width=36)

 ->  HashAggregate  (cost=13506.81..13506.83 rows=1 width=36)

       ->  Nested Loop  (cost=58.47..13506.81 rows=1 width=36)

             ->  Nested Loop  (cost=58.47..13503.10 rows=1 width=36)

                   ->  Nested Loop  (cost=58.47..13499.67 rows=1 width=24)

                         ->  Nested Loop  (cost=58.47..13496.64 rows=1
width=24)

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

                               ->  Nested Loop  (cost=58.47..78.41 rows=1
width=
28)

                                     ->  Index Scan using answers_answer_un
on a
nswers a  (cost=0.00..4.01 rows=1 width=28)

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

                                     ->  Bitmap Heap Scan on
questions_answers q
a  (cost=58.47..74.30 rows=8 width=16)

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

                                           ->  BitmapAnd  (cost=58.47..58.47
row
s=8 width=0)

                                                 ->  Bitmap Index Scan on
qs_as_
answer_id  (cost=0.00..5.37 rows=677 width=0)

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

                                                 ->  BitmapOr
(cost=52.85..52.8
5 rows=6530 width=0)

                                                       ->  Bitmap Index Scan
on
qs_as_qtag  (cost=0.00..26.43 rows=3265 width=0)


                                                             Index Cond:
((quest
ion_tag)::text = 'consentTransfer'::text)

                                                       ->  Bitmap Index Scan
on
qs_as_qtag  (cost=0.00..26.43 rows=3265 width=0)

                                                             Index Cond:
((quest
ion_tag)::text = 'shareWithEval'::text)

                               ->  Seq Scan on encounters_questions_answers
eqa
 (cost=0.00..7608.66 rows=464766 width=8)

                         ->  Index Scan using encounters_id on encounters ec
(c
ost=0.00..3.01 rows=1 width=8)

                               Index Cond: (ec.id = "outer".encounter_id)

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

                         Index Cond: ("outer".enrollment_id = en.id)

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

                   Index Cond: (p.id = "outer".person_id)

 ->  HashAggregate  (cost=88.22..88.24 rows=1 width=36)

       ->  Nested Loop  (cost=58.47..88.22 rows=1 width=36)

             ->  Nested Loop  (cost=58.47..84.51 rows=1 width=36)

                   ->  Nested Loop  (cost=58.47..81.43 rows=1 width=24)

                         ->  Nested Loop  (cost=58.47..78.41 rows=1
width=28)

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

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

                               ->  Bitmap Heap Scan on questions_answers qa
(co
st=58.47..74.30 rows=8 width=16)
                                     Recheck Cond: ((qa.answer_id =
"outer".id)
AND (((qa.question_tag)::text = 'consentTransfer'::text) OR
((qa.question_tag)::
text = 'shareWithEval'::text)))

                                     ->  BitmapAnd  (cost=58.47..58.47
rows=8 wi
dth=0)

                                           ->  Bitmap Index Scan on
qs_as_answer
_id  (cost=0.00..5.37 rows=677 width=0)

                                                 Index Cond: (qa.answer_id =
"ou
ter".id)

                                           ->  BitmapOr  (cost=52.85..52.85
rows
=6530 width=0)

                                                 ->  Bitmap Index Scan on
qs_as_
qtag  (cost=0.00..26.43 rows=3265 width=0)

                                                       Index Cond:
((question_ta
g)::text = 'consentTransfer'::text)

                                                 ->  Bitmap Index Scan on
qs_as_

qtag  (cost=0.00..26.43 rows=3265 width=0)

                                                       Index Cond:
((question_ta
g)::text = 'shareWithEval'::text)

                         ->  Index Scan using ctccalls_qs_as_qaid on
ctccalls_qu
estions_answers cqa  (cost=0.00..3.02 rows=1 width=8)

                               Index Cond: (cqa.question_answer_id =
"outer".id)

                   ->  Index Scan using ctccalls_pk on ctccalls c
(cost=0.00..3
.06 rows=1 width=20)

                         Index Cond: (c.id = "outer".call_id)

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

                   Index Cond: (p.id = "outer".person_id)
                                 ->  Index Scan using people_pk on people
(cost
=0.00..3.69 rows=1 width=816)
                                       Index Cond: (people.id = "outer".id)
                           ->  Subquery Scan "*SELECT* 2"
(cost=13595.18..13890
.35 rows=3119 width=677)
                                 ->  Seq Scan on people
(cost=13595.18..13859.1
6 rows=3119 width=677)
                                       Filter: (NOT (hashed subplan))
                                       SubPlan
                                         ->  Subquery Scan temp_consent2
(cost=
13595.14..13595.18 rows=2 width=8)
                                               ->  Unique
(cost=13595.14..13595
.16 rows=2 width=16)
                                                     ->  Sort
(cost=13595.14..1
3595.15 rows=2 width=16)
                                                           Sort Key:
temp_consen
t.daterecorded, temp_consent.id
                                                           ->  Subquery Scan
tem
p_consent  (cost=13595.09..13595.13 rows=2 width=16)
                                                                 ->  Unique
(co
st=13595.09..13595.11 rows=2 width=36)
                                                                       ->
Sort
 (cost=13595.09..13595.10 rows=2 width=36)

Sor
t Key: id, daterecorded, answer

->
 Append  (cost=13506.81..13595.08 rows=2 width=36)


   ->  HashAggregate  (cost=13506.81..13506.83 rows=1 width=36)

         ->  Nested Loop  (cost=58.47..13506.81 rows=1 width=36)

               ->  Nested Loop  (cost=58.47..13503.10 rows=1 width=36)

                     ->  Nested Loop  (cost=58.47..13499.67 rows=1 width=24)

                           ->  Nested Loop  (cost=58.47..13496.64 rows=1
width=2
4)

                                 Join Filter: ("inner".question_answer_id =
"out
er".id)

                                 ->  Nested Loop  (cost=58.47..78.41 rows=1
widt
h=28)

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

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

                                       ->  Bitmap Heap Scan on
questions_answers
 qa  (cost=58.47..74.30 rows=8 width=16)

                                             Recheck Cond: ((qa.answer_id =
"out
er".id) AND (((qa.question_tag)::text = 'consentTransfer'::text) OR
((qa.questio
n_tag)::text = 'shareWithEval'::text)))

                                             ->  BitmapAnd
(cost=58.47..58.47 r
ows=8 width=0)

                                                   ->  Bitmap Index Scan on
qs_a
s_answer_id  (cost=0.00..5.37 rows=677 width=0)

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

                                                   ->  BitmapOr
(cost=52.85..52
.85 rows=6530 width=0)

                                                         ->  Bitmap Index
Scan o
n qs_as_qtag  (cost=0.00..26.43 rows=3265 width=0)

                                                               Index Cond:
((que
stion_tag)::text = 'consentTransfer'::text)

                                                         ->  Bitmap Index
Scan o
n qs_as_qtag  (cost=0.00..26.43 rows=3265 width=0)

                                                               Index Cond:
((que
stion_tag)::text = 'shareWithEval'::text)

                                 ->  Seq Scan on
encounters_questions_answers eq
a  (cost=0.00..7608.66 rows=464766 width=8)

                           ->  Index Scan using encounters_id on encounters
ec
(cost=0.00..3.01 rows=1 width=8)

                                 Index Cond: (ec.id = "outer".encounter_id)

                     ->  Index Scan using enrollements_pk on enrollments en
(co
st=0.00..3.42 rows=1 width=20)

                           Index Cond: ("outer".enrollment_id = en.id)

               ->  Index Scan using people_pk on people p  (cost=0.00..3.69
rows

=1 width=8)

                     Index Cond: (p.id = "outer".person_id)

   ->  HashAggregate  (cost=88.22..88.24 rows=1 width=36)

         ->  Nested Loop  (cost=58.47..88.22 rows=1 width=36)

               ->  Nested Loop  (cost=58.47..84.51 rows=1 width=36)

                     ->  Nested Loop  (cost=58.47..81.43 rows=1 width=24)

                           ->  Nested Loop  (cost=58.47..78.41 rows=1
width=28)

                                 ->  Index Scan using answers_answer_un on
answe
rs a  (cost=0.00..4.01 rows=1 width=28)

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

                                 ->  Bitmap Heap Scan on questions_answers
qa  (
cost=58.47..74.30 rows=8 width=16)

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

                                       ->  BitmapAnd  (cost=58.47..58.47
rows=8
width=0)

                                             ->  Bitmap Index Scan on
qs_as_answ
er_id  (cost=0.00..5.37 rows=677 width=0)

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

                                             ->  BitmapOr
(cost=52.85..52.85 ro
ws=6530 width=0)

                                                   ->  Bitmap Index Scan on
qs_a
s_qtag  (cost=0.00..26.43 rows=3265 width=0)

                                                         Index Cond:
((question_
tag)::text = 'consentTransfer'::text)

                                                   ->  Bitmap Index Scan on
qs_a

                                                   ->  Bitmap Index Scan on
qs_a
s_qtag  (cost=0.00..26.43 rows=3265 width=0)

                                                         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)

                                 Index Cond: (cqa.question_answer_id =
"outer".i
d)

                     ->  Index Scan using ctccalls_pk on ctccalls c
(cost=0.00.
.3.06 rows=1 width=20)

                           Index Cond: (c.id = "outer".call_id)

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

                     Index Cond: (p.id = "outer".person_id)
(131 rows)




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


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

From
Richard Huxton
Date:
smiley2211 wrote:
> Here is the EXPLAIN after I changed some conf file - now I am running another
> EXPLAIN ANALYZE which may take 5 or more hours to complete :,(
>
> effective_cache = 170000

Why has effective_cache changed from 80,000 to 170,000 - have you
stopped running some other application?

> enable_seqscan = on
> enable _bitmapscan = on

Why were these disabled before? What were you trying to achieve? What
has now changed?

>  QUERY PLAN

You still haven't supplied the query. However, looking at the explain
I'd guess there's a lot of sorting going on? You might want to increase
work_mem just for this query:

SET work_mem = ...;
SELECT ...

However, that's just a blind guess because you haven't supplied the
absolutely vital information:
1. The query
2. An idea of how many rows are in the relevant tables
3. The "I have vacuumed and analysed recently" disclaimer
4. The explain analyse (which you are running - good, make sure you save
a copy of it somwhere).

Even then it'll be difficult to get a quick answer because it looks like
a large query. So - you can speed things along by looking for oddities
yourself.

The explain analyse will have two values for "rows" on each line, the
predicted and the actual - look for where they are wildly different. If
the planner is expecting 2 matches and seeing 2000 it might make the
wrong choice. You can usually cut down the large query to test just this
section. Then you might want to read up about "ALTER TABLE ... SET
STATISTICS" - that might give the planner more to work with.

The other thing to look for is the time. The explain analyse has two
figures for "actual time". These are startup and total time for that
node (if "loops" is > 1 then multiply the time by the number of loop
iterations). It might be there are one or two nodes that are taking a
long time and we can find out why then.

HTH

--
   Richard Huxton
   Archonet Ltd

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

From
smiley2211
Date:
Here are the VIEWS in question: query = (explain analyze select id from
people_consent LIMIT 1;)

CREATE OR REPLACE VIEW temp_consent AS
 SELECT p.id, max(en.enrolled_at) AS daterecorded, a.answer
   FROM people p, enrollments en, encounters ec,
encounters_questions_answers eqa, questions_answers qa, answers a
  WHERE (qa.question_tag::text = 'consentTransfer'::text OR
qa.question_tag::text = 'shareWithEval'::text) AND eqa.question_answer_id =
qa.id AND ec.id = eqa.encounter_id AND ec.enrollment_id = en.id AND p.id =
en.person_id AND qa.answer_id = a.id
  GROUP BY p.id, a.answer
UNION
 SELECT p.id, max(c.entered_at) AS daterecorded, a.answer
   FROM people p, ctccalls c, ctccalls_questions_answers cqa,
questions_answers qa, answers a
  WHERE (qa.question_tag::text = 'consentTransfer'::text OR
qa.question_tag::text = 'shareWithEval'::text) AND cqa.question_answer_id =
qa.id AND c.id = cqa.call_id AND p.id = c.person_id AND qa.answer_id = a.id
  GROUP BY p.id, a.answer;


CREATE OR REPLACE VIEW temp_consent2 AS
 SELECT DISTINCT temp_consent.id, temp_consent.daterecorded
   FROM temp_consent
  WHERE temp_consent.answer::text = 'Yes'::text
  ORDER BY temp_consent.daterecorded DESC, temp_consent.id;


CREATE OR REPLACE VIEW people_consent AS
 SELECT people.id, people.firstname, people.lastname, people.homephone,
people.workphone, people.altphone, people.eligibilityzipcode,
people.address1, people.address2, people.city, people.state,
people.zipcode1, people.zipcode2, people.email, people.dayofbirth,
people.monthofbirth, people.yearofbirth, people.ethnic_detail,
people.external_id, people.highestlevelofeducation_id,
people.ethnicgroup_id, people.ethnicotherrace, people.entered_at,
people.entered_by, people.besttimetoreach_id, people.language_id,
people.otherlanguage, people.gender_id, people.hispaniclatino_id,
people.canscheduleapt_id, people.mayweleaveamessage_id, people.ethnictribe,
people.ethnicasian, people.ethnicislander
   FROM people
  WHERE (people.id IN ( SELECT temp_consent2.id
           FROM temp_consent2))
UNION
 SELECT people.id, '***MASKED***' AS firstname, '***MASKED***' AS lastname,
'***MASKED***' AS homephone, '***MASKED***' AS workphone, '***MASKED***' AS
altphone, '***MASKED***' AS eligibilityzipcode, '***MASKED***' AS address1,
'***MASKED***' AS address2, '***MASKED***' AS city, '***MASKED***' AS state,
'***MASKED***' AS zipcode1, '***MASKED***' AS zipcode2, people.email,
'***MASKED***' AS dayofbirth, '***MASKED***' AS monthofbirth, '***MASKED***'
AS yearofbirth, people.ethnic_detail, people.external_id,
people.highestlevelofeducation_id, people.ethnicgroup_id,
people.ethnicotherrace, people.entered_at, people.entered_by,
people.besttimetoreach_id, people.language_id, people.otherlanguage,
people.gender_id, people.hispaniclatino_id, people.canscheduleapt_id,
people.mayweleaveamessage_id, people.ethnictribe, people.ethnicasian,
people.ethnicislander
   FROM people
  WHERE NOT (people.id IN ( SELECT temp_consent2.id
           FROM temp_consent2));

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


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

From
"Chris Hoover"
Date:
On 7/3/07, smiley2211 <smiley2211@yahoo.com> wrote:

CREATE OR REPLACE VIEW temp_consent2 AS
SELECT DISTINCT temp_consent.id, temp_consent.daterecorded
   FROM temp_consent
  WHERE temp_consent.answer::text = 'Yes'::text
  ORDER BY temp_consent.daterecorded DESC, temp_consent.id;


Get rid of the order by on this view.  It is  a waste of resources.  If you need it ordered else where, order it on the fly i.e. select * from temp_consent2 order by .....

CREATE OR REPLACE VIEW people_consent AS
SELECT people.id, people.firstname, people.lastname, people.homephone,
people.workphone, people.altphone, people.eligibilityzipcode,
people.address1 , people.address2, people.city, people.state,
people.zipcode1, people.zipcode2, people.email, people.dayofbirth,
people.monthofbirth, people.yearofbirth, people.ethnic_detail,
people.external_id, people.highestlevelofeducation_id ,
people.ethnicgroup_id, people.ethnicotherrace, people.entered_at,
people.entered_by, people.besttimetoreach_id, people.language_id,
people.otherlanguage, people.gender_id, people.hispaniclatino_id,
people.canscheduleapt_id , people.mayweleaveamessage_id, people.ethnictribe,
people.ethnicasian, people.ethnicislander
   FROM people
  WHERE (people.id IN ( SELECT temp_consent2.id
           FROM temp_consent2))
UNION
SELECT people.id, '***MASKED***' AS firstname, '***MASKED***' AS lastname,
'***MASKED***' AS homephone, '***MASKED***' AS workphone, '***MASKED***' AS
altphone, '***MASKED***' AS eligibilityzipcode, '***MASKED***' AS address1,
'***MASKED***' AS address2, '***MASKED***' AS city, '***MASKED***' AS state,
'***MASKED***' AS zipcode1, '***MASKED***' AS zipcode2, people.email,
'***MASKED***' AS dayofbirth, '***MASKED***' AS monthofbirth, '***MASKED***'
AS yearofbirth, people.ethnic_detail, people.external_id,
people.highestlevelofeducation_id, people.ethnicgroup_id ,
people.ethnicotherrace, people.entered_at, people.entered_by,
people.besttimetoreach_id, people.language_id, people.otherlanguage,
people.gender_id, people.hispaniclatino_id, people.canscheduleapt_id,
people.mayweleaveamessage_id , people.ethnictribe, people.ethnicasian,
people.ethnicislander
   FROM people
  WHERE NOT (people.id IN ( SELECT temp_consent2.id
           FROM temp_consent2));


Try linking the people and temp_consent2 like this
where people.id not in (select temp_consent2.id from temp_consent2 where temp_consent2.id = people.id )

That will help a lot.

HTH,

Chris

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

From
smiley2211
Date:
TOP shows CPU at 100% while executed the EXPLAIN ANALYZE...what does this
mean?

17519 postgres  25   0 3470m  43m  39m R  100  0.3  28:50.53 postmaster
--
View this message in context:
http://www.nabble.com/Query-is-taking-5-HOURS-to-Complete-on-8.1-version-tf4019778.html#a11419885
Sent from the PostgreSQL - performance mailing list archive at Nabble.com.


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

From
Richard Huxton
Date:
smiley2211 wrote:
> Here are the VIEWS in question: query = (explain analyze select id from
> people_consent LIMIT 1;)

First thing I notice - you don't have any ordering, so the LIMIT isn't
returning a well-defined record. Might not matter in your particular
context.

> CREATE OR REPLACE VIEW temp_consent AS
>  SELECT p.id, max(en.enrolled_at) AS daterecorded, a.answer
>    FROM people p, enrollments en, encounters ec,
> encounters_questions_answers eqa, questions_answers qa, answers a
>   WHERE (qa.question_tag::text = 'consentTransfer'::text OR
> qa.question_tag::text = 'shareWithEval'::text) AND eqa.question_answer_id =
> qa.id AND ec.id = eqa.encounter_id AND ec.enrollment_id = en.id AND p.id =
> en.person_id AND qa.answer_id = a.id
>   GROUP BY p.id, a.answer
> UNION

I think you might be able to make this "UNION ALL" - a UNION will check
for duplicates and eliminate them. That's a match on
(id,daterecorded,answer) from both sub-queries - can that happen and do
you care?

>  SELECT p.id, max(c.entered_at) AS daterecorded, a.answer
>    FROM people p, ctccalls c, ctccalls_questions_answers cqa,
> questions_answers qa, answers a
>   WHERE (qa.question_tag::text = 'consentTransfer'::text OR
> qa.question_tag::text = 'shareWithEval'::text) AND cqa.question_answer_id =
> qa.id AND c.id = cqa.call_id AND p.id = c.person_id AND qa.answer_id = a.id
>   GROUP BY p.id, a.answer;
>
>
> CREATE OR REPLACE VIEW temp_consent2 AS
>  SELECT DISTINCT temp_consent.id, temp_consent.daterecorded
>    FROM temp_consent
>   WHERE temp_consent.answer::text = 'Yes'::text
>   ORDER BY temp_consent.daterecorded DESC, temp_consent.id;

Not sure what the DISTINCT is doing for us here. You've eliminated
duplicates in the previous view and so you can't have more than one
(id,daterecorded) for any given answer. (Assuming you keep the previous
UNION in)

> CREATE OR REPLACE VIEW people_consent AS
>  SELECT people.id, people.firstname, people.lastname, people.homephone,
> people.workphone, people.altphone, people.eligibilityzipcode,
> people.address1, people.address2, people.city, people.state,
> people.zipcode1, people.zipcode2, people.email, people.dayofbirth,
> people.monthofbirth, people.yearofbirth, people.ethnic_detail,
> people.external_id, people.highestlevelofeducation_id,
> people.ethnicgroup_id, people.ethnicotherrace, people.entered_at,
> people.entered_by, people.besttimetoreach_id, people.language_id,
> people.otherlanguage, people.gender_id, people.hispaniclatino_id,
> people.canscheduleapt_id, people.mayweleaveamessage_id, people.ethnictribe,
> people.ethnicasian, people.ethnicislander
>    FROM people
>   WHERE (people.id IN ( SELECT temp_consent2.id
>            FROM temp_consent2))
> UNION
>  SELECT people.id, '***MASKED***' AS firstname, '***MASKED***' AS lastname,
> '***MASKED***' AS homephone, '***MASKED***' AS workphone, '***MASKED***' AS
> altphone, '***MASKED***' AS eligibilityzipcode, '***MASKED***' AS address1,
> '***MASKED***' AS address2, '***MASKED***' AS city, '***MASKED***' AS state,
> '***MASKED***' AS zipcode1, '***MASKED***' AS zipcode2, people.email,
> '***MASKED***' AS dayofbirth, '***MASKED***' AS monthofbirth, '***MASKED***'
> AS yearofbirth, people.ethnic_detail, people.external_id,
> people.highestlevelofeducation_id, people.ethnicgroup_id,
> people.ethnicotherrace, people.entered_at, people.entered_by> people.besttimetoreach_id, people.language_id,
people.otherlanguage,
> people.gender_id, people.hispaniclatino_id, people.canscheduleapt_id,
> people.mayweleaveamessage_id, people.ethnictribe, people.ethnicasian,
> people.ethnicislander
>    FROM people
>   WHERE NOT (people.id IN ( SELECT temp_consent2.id
>            FROM temp_consent2));

OK, well the UNION here can certainly be UNION ALL.
1. You're using "***MASKED***" for a bunch of fields, so unless they're
occurring naturally in "people" you won't get duplicates.
2. Your WHERE clauses are the complement of each other.

One other point NOT (people.id IN...) would perhaps be usually written
as "people.id NOT IN (...)". The planner should realise they're the same
though.

However, there's one obvious thing you can do. As it stands you're
testing against temp_consent2 twice. You could rewrite the query
something like:

SELECT
   people.id,
   CASE WHEN temp_consent2.id IS NULL
     THEN '***MASKED***'
     ELSE people.firstname
   END AS firstname
   ...
FROM
   people LEFT JOIN temp_consent2 ON people.id=temp_consent2.id
;

You might want to try these tweaks, but I'd start by working with
temp_consent and seeing how long that takes to execute. Then work out.

--
   Richard Huxton
   Archonet Ltd

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

From
Richard Huxton
Date:
smiley2211 wrote:
> TOP shows CPU at 100% while executed the EXPLAIN ANALYZE...what does this
> mean?
>
> 17519 postgres  25   0 3470m  43m  39m R  100  0.3  28:50.53 postmaster

It means it's busy. Probably sorting/eliminating duplicates (see my
answer posted just before this one).

Keep an eye on "vmstat" too and see if there's much disk activity.

--
   Richard Huxton
   Archonet Ltd

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

From
smiley2211
Date:
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.


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

From
Alvaro Herrera
Date:
smiley2211 wrote:
>
> 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:

It seems you have disabled nested loops --- why?  Try turning them back
on and let us see the EXPLAIN ANALYZE again.

It would be extremely helpful if you saved it in a file and attached it
separately so that the indentation and whitespace is not mangled by your
email system.  It would be a lot more readable that way.

--
Alvaro Herrera                                http://www.CommandPrompt.com/
PostgreSQL Replication, Consulting, Custom Development, 24x7 support