Folks:
I have a live and a test database for an in-production system running on
7.2.4.
The test database is a copy of the live one. They are running on the same
copy of Postgres, on the same server. I use the test database to test
changes before I apply them to the production system. Periodically (like
today) I reload the test system from the backup of the live one.
I'm now having a problem with a huge complex query which runs very slowly on
the test database, but very quickly on the live database! The problems
seems to be that the test database seems to think that a nested loop is an
appropriate strategy for a table of 140,000 records, while the live one
realizes that it's not.
What really has me scratching my head is that the test database is an exact
copy of the live database, just a few hours older. And the live database has
never displayed this performance problem, whereas the test database has had
it for 2-3 weeks.
Both EXPLAIN ANALYZEs are attached.
--
-Josh Berkus
Aglio Database Solutions
San Francisco
Sort (cost=57376.11..57376.11 rows=1 width=627) (actual time=370.48..370.48 rows=8
loops=1)
-> Nested Loop (cost=57049.91..57376.10 rows=1 width=627) (actual
time=360.99..369.81 rows=8 loops=1)
-> Nested Loop (cost=57049.91..57372.18 rows=1 width=583) (actual
time=314.97..320.96 rows=8 loops=1)
-> Nested Loop (cost=57049.91..57368.25 rows=1 width=539) (actual
time=314.90..320.56 rows=8 loops=1)
-> Nested Loop (cost=57049.91..57365.27 rows=1 width=525)
(actual time=314.42..317.60 rows=8 loops=1)
-> Nested Loop (cost=57049.91..57361.78 rows=1 width=497)
(actual time=314.35..317.10 rows=8 loops=1)
-> Nested Loop (cost=57049.91..57357.83 rows=1
width=436) (actual time=314.27..316.53 rows=8 loops=1)
-> Merge Join (cost=57049.91..57050.46 rows=77
width=424) (actual time=314.02..314.77 rows=26 loops=1)
-> Sort (cost=57048.31..57048.31 rows=37
width=406) (actual time=313.76..313.78 rows=27 loops=1)
-> Merge Join
(cost=57019.29..57047.82 rows=37 width=406) (actual time=311.61..313.63 rows=27
loops=1)
-> Index Scan using
locations_pkey on locations (cost=0.00..27.54 rows=568 width=107) (actual
time=0.22..1.55 rows=172 loops=1)
-> Sort
(cost=57019.29..57019.29 rows=37 width=299) (actual time=311.34..311.35 rows=27
loops=1)
-> Hash Join
(cost=5.73..57018.80 rows=37 width=299) (actual time=44.24..311.12 rows=27 loops=1)
-> Hash Join
(cost=4.61..57015.58 rows=745 width=274) (actual time=3.30..308.58 rows=965 loops=1)
-> Index
Scan using idx_events_date on events (cost=0.00..57004.46 rows=745 width=240) (actual
time=2.54..296.46 rows=965 loops=1)
SubPlan
->
Nested Loop (cost=5.48..19.48 rows=1 width=55) (actual time=0.05..0.05 rows=0
loops=856)
-> Nested Loop (cost=0.00..12.52 rows=1 width=23) (actual time=0.03..0.04 rows=0
loops=856)
-> Nested Loop (cost=0.00..7.41 rows=1 width=12) (actual time=0.01..0.02
rows=1 loops=856)
-> Index Scan using trial_groups_pkey on trial_groups (cost=0.00..3.49
rows=1 width=4) (actual time=0.01..0.01 rows=0 loops=856)
-> Index Scan using idx_cases_tgroup on cases (cost=0.00..3.92 rows=1
width=8) (actual time=0.02..0.04 rows=4 loops=133)
-> Index Scan using idx_caseclients_case on case_clients (cost=0.00..5.10
rows=1 width=11) (actual time=0.03..0.04 rows=1 loops=471)
-> Materialize (cost=6.95..6.95 rows=1 width=32) (actual time=0.00..0.00 rows=3
loops=366)
-> Nested Loop (cost=5.48..6.95 rows=1 width=32) (actual time=0.58..0.81
rows=3 loops=1)
-> Merge Join (cost=5.48..5.50 rows=1 width=30) (actual time=0.55..0.56
rows=3 loops=1)
-> Sort (cost=4.04..4.04 rows=2 width=28) (actual time=0.39..0.39
rows=3 loops=1)
-> Merge Join (cost=3.99..4.03 rows=2 width=28) (actual
time=0.31..0.32 rows=3 loops=1)
-> Sort (cost=1.34..1.34 rows=21 width=8) (actual
time=0.12..0.12 rows=2 loops=1)
-> Seq Scan on text_lists (cost=0.00..1.10
rows=21 width=8) (actual time=0.01..0.06 rows=21 loops=1)
-> Sort (cost=2.65..2.65 rows=2 width=20) (actual
time=0.18..0.18 rows=3 loops=1)
-> Seq Scan on list_values (cost=0.00..2.65
rows=2 width=20) (actual time=0.01..0.15 rows=3 loops=1)
-> Sort (cost=1.45..1.45 rows=3 width=2) (actual time=0.13..0.13
rows=5 loops=1)
-> Seq Scan on status s1 (cost=0.00..1.44 rows=3 width=2)
(actual time=0.01..0.09 rows=4 loops=1)
-> Seq Scan on status s2 (cost=0.00..1.44 rows=3 width=2) (actual
time=0.01..0.07 rows=3 loops=3)
->
Nested Loop (cost=5.48..16.00 rows=1 width=47) (actual time=0.06..0.06 rows=0
loops=3325)
-> Nested Loop (cost=0.00..9.05 rows=1 width=15) (actual time=0.05..0.06 rows=1
loops=3325)
-> Index Scan using cases_pkey on cases (cost=0.00..3.94 rows=1 width=4)
(actual time=0.02..0.02 rows=1 loops=3325)
-> Index Scan using idx_caseclients_case on case_clients (cost=0.00..5.10
rows=1 width=11) (actual time=0.03..0.03 rows=1 loops=3311)
-> Materialize (cost=6.95..6.95 rows=1 width=32) (actual time=0.00..0.00 rows=2
loops=2190)
-> Nested Loop (cost=5.48..6.95 rows=1 width=32) (actual time=0.63..0.85
rows=3 loops=1)
-> Merge Join (cost=5.48..5.50 rows=1 width=30) (actual time=0.59..0.60
rows=3 loops=1)
-> Sort (cost=4.04..4.04 rows=2 width=28) (actual time=0.43..0.43
rows=3 loops=1)
-> Merge Join (cost=3.99..4.03 rows=2 width=28) (actual
time=0.35..0.36 rows=3 loops=1)
-> Sort (cost=1.34..1.34 rows=21 width=8) (actual
time=0.14..0.14 rows=2 loops=1)
-> Seq Scan on text_lists (cost=0.00..1.10
rows=21 width=8) (actual time=0.02..0.06 rows=21 loops=1)
-> Sort (cost=2.65..2.65 rows=2 width=20) (actual
time=0.19..0.20 rows=3 loops=1)
-> Seq Scan on list_values (cost=0.00..2.65
rows=2 width=20) (actual time=0.02..0.17 rows=3 loops=1)
-> Sort (cost=1.45..1.45 rows=3 width=2) (actual time=0.14..0.14
rows=5 loops=1)
-> Seq Scan on status s1 (cost=0.00..1.44 rows=3 width=2)
(actual time=0.02..0.10 rows=4 loops=1)
-> Seq Scan on status s2 (cost=0.00..1.44 rows=3 width=2) (actual
time=0.01..0.07 rows=3 loops=3)
-> Hash
(cost=4.49..4.49 rows=97 width=34) (actual time=0.52..0.52 rows=0 loops=1)
->
Seq Scan on event_types (cost=0.00..4.49 rows=97 width=34) (actual time=0.06..0.38
rows=97 loops=1)
-> Hash
(cost=1.12..1.12 rows=1 width=25) (actual time=0.09..0.09 rows=0 loops=1)
-> Seq Scan
on event_cats (cost=0.00..1.12 rows=1 width=25) (actual time=0.07..0.08 rows=1
loops=1)
-> Sort (cost=1.61..1.61 rows=10
width=18) (actual time=0.21..0.23 rows=30 loops=1)
-> Seq Scan on status
(cost=0.00..1.52 rows=10 width=18) (actual time=0.04..0.12 rows=9 loops=1)
-> Index Scan using event_days_pk on event_days
(cost=0.00..3.96 rows=1 width=12) (actual time=0.05..0.05 rows=0 loops=26)
-> Index Scan using cases_pkey on cases
(cost=0.00..3.94 rows=1 width=61) (actual time=0.02..0.03 rows=0 loops=8)
-> Index Scan using trial_groups_pkey on trial_groups
(cost=0.00..3.49 rows=1 width=28) (actual time=0.01..0.02 rows=0 loops=8)
-> Seq Scan on opp_counsel (cost=0.00..2.44 rows=87 width=14)
(actual time=0.01..0.18 rows=87 loops=8)
-> Index Scan using events_pkey on events parent (cost=0.00..3.92
rows=1 width=44) (actual time=0.00..0.00 rows=0 loops=8)
-> Index Scan using events_pkey on events previous (cost=0.00..3.92 rows=1
width=44) (actual time=0.02..0.02 rows=0 loops=8)
SubPlan
-> Aggregate (cost=9.01..9.01 rows=1 width=23) (actual time=0.35..0.35
rows=1 loops=4)
-> Index Scan using idx_cases_tgroup on cases c1 (cost=0.00..9.01
rows=1 width=23) (actual time=0.08..0.23 rows=4 loops=4)
SubPlan
-> Index Scan using idx_caseclients_case on case_clients cc1
(cost=0.00..5.09 rows=1 width=7) (actual time=0.03..0.03 rows=1 loops=22)
Total runtime: 373.70 msec
Sort (cost=8725694.92..8725694.92 rows=1 width=625) (actual time=266461.38..266461.38
rows=8 loops=1)
-> Nested Loop (cost=8725228.42..8725694.91 rows=1 width=625) (actual
time=266452.64..266461.09 rows=8 loops=1)
-> Nested Loop (cost=8725228.42..8725691.01 rows=1 width=581) (actual
time=266442.99..266448.67 rows=8 loops=1)
-> Nested Loop (cost=8725228.42..8725687.12 rows=1 width=537) (actual
time=266442.93..266448.29 rows=8 loops=1)
-> Nested Loop (cost=8725228.42..8725684.14 rows=1 width=523)
(actual time=266442.45..266445.48 rows=8 loops=1)
-> Nested Loop (cost=8725228.42..8725680.64 rows=1
width=495) (actual time=266442.38..266444.99 rows=8 loops=1)
-> Nested Loop (cost=8725228.42..8725676.67 rows=1
width=434) (actual time=266442.30..266444.43 rows=8 loops=1)
-> Merge Join (cost=8725228.42..8725229.20
rows=113 width=422) (actual time=266442.08..266442.77 rows=26 loops=1)
-> Sort (cost=8725226.81..8725226.81
rows=54 width=404) (actual time=266441.54..266441.56 rows=27 loops=1)
-> Merge Join
(cost=8725197.37..8725226.03 rows=54 width=404) (actual time=266439.42..266441.41
rows=27 loops=1)
-> Index Scan using
locations_pkey on locations (cost=0.00..27.54 rows=568 width=107) (actual
time=0.14..1.44 rows=172 loops=1)
-> Sort
(cost=8725197.37..8725197.37 rows=54 width=297) (actual time=266439.24..266439.25
rows=27 loops=1)
-> Hash Join
(cost=5.73..8725196.59 rows=54 width=297) (actual time=28490.20..266438.99 rows=27
loops=1)
-> Hash Join
(cost=4.60..8725192.42 rows=1083 width=272) (actual time=2.25..266436.04 rows=964
loops=1)
-> Index
Scan using idx_events_date on events (cost=0.00..8725178.35 rows=1083 width=238)
(actual time=1.49..266421.59 rows=964 loops=1)
SubPlan
->
Hash Join (cost=89.59..3792.14 rows=1 width=55) (actual time=311.23..311.23 rows=0
loops=855)
-> Hash Join (cost=82.64..3784.86 rows=88 width=23) (actual time=301.99..310.66
rows=0 loops=855)
-> Seq Scan on case_clients (cost=0.00..3673.48 rows=11274 width=11) (actual
time=0.02..302.20 rows=8822 loops=855)
-> Hash (cost=81.53..81.53 rows=887 width=12) (actual time=0.04..0.04 rows=0
loops=855)
-> Nested Loop (cost=0.00..81.53 rows=887 width=12) (actual
time=0.03..0.04 rows=1 loops=855)
-> Index Scan using trial_groups_pkey on trial_groups
(cost=0.00..3.49 rows=1 width=4) (actual time=0.02..0.02 rows=0 loops=855)
-> Index Scan using idx_cases_tgroup on cases (cost=0.00..77.77
rows=43 width=8) (actual time=0.03..0.07 rows=6 loops=133)
-> Hash (cost=6.95..6.95 rows=1 width=32) (actual time=0.30..0.30 rows=0 loops=855)
-> Nested Loop (cost=5.48..6.95 rows=1 width=32) (actual time=0.06..0.30
rows=3 loops=855)
-> Merge Join (cost=5.48..5.50 rows=1 width=30) (actual time=0.02..0.04
rows=3 loops=855)
-> Sort (cost=4.04..4.04 rows=2 width=28) (actual time=0.00..0.00
rows=3 loops=855)
-> Merge Join (cost=3.99..4.03 rows=2 width=28) (actual
time=0.30..0.30 rows=3 loops=1)
-> Sort (cost=1.34..1.34 rows=21 width=8) (actual
time=0.11..0.11 rows=2 loops=1)
-> Seq Scan on text_lists (cost=0.00..1.10
rows=21 width=8) (actual time=0.01..0.05 rows=21 loops=1)
-> Sort (cost=2.65..2.65 rows=2 width=20) (actual
time=0.18..0.18 rows=3 loops=1)
-> Seq Scan on list_values (cost=0.00..2.65
rows=2 width=20) (actual time=0.01..0.14 rows=3 loops=1)
-> Sort (cost=1.45..1.45 rows=3 width=2) (actual time=0.00..0.00
rows=5 loops=855)
-> Seq Scan on status s1 (cost=0.00..1.44 rows=3 width=2)
(actual time=0.01..0.08 rows=4 loops=1)
-> Seq Scan on status s2 (cost=0.00..1.44 rows=3 width=2) (actual
time=0.01..0.07 rows=3 loops=2565)
->
Nested Loop (cost=5.48..15.71 rows=1 width=47) (actual time=0.07..0.07 rows=0
loops=3312)
-> Nested Loop (cost=0.00..8.76 rows=1 width=15) (actual time=0.06..0.07 rows=1
loops=3312)
-> Index Scan using cases_pkey on cases (cost=0.00..3.96 rows=1 width=4)
(actual time=0.02..0.02 rows=1 loops=3312)
-> Index Scan using idx_caseclients_case on case_clients (cost=0.00..4.79
rows=1 width=11) (actual time=0.03..0.03 rows=1 loops=3298)
-> Materialize (cost=6.95..6.95 rows=1 width=32) (actual time=0.00..0.00 rows=2
loops=2182)
-> Nested Loop (cost=5.48..6.95 rows=1 width=32) (actual time=0.68..0.89
rows=3 loops=1)
-> Merge Join (cost=5.48..5.50 rows=1 width=30) (actual time=0.64..0.66
rows=3 loops=1)
-> Sort (cost=4.04..4.04 rows=2 width=28) (actual time=0.50..0.50
rows=3 loops=1)
-> Merge Join (cost=3.99..4.03 rows=2 width=28) (actual
time=0.42..0.43 rows=3 loops=1)
-> Sort (cost=1.34..1.34 rows=21 width=8) (actual
time=0.16..0.16 rows=2 loops=1)
-> Seq Scan on text_lists (cost=0.00..1.10
rows=21 width=8) (actual time=0.06..0.09 rows=21 loops=1)
-> Sort (cost=2.65..2.65 rows=2 width=20) (actual
time=0.24..0.24 rows=3 loops=1)
-> Seq Scan on list_values (cost=0.00..2.65
rows=2 width=20) (actual time=0.06..0.20 rows=3 loops=1)
-> Sort (cost=1.45..1.45 rows=3 width=2) (actual time=0.12..0.12
rows=5 loops=1)
-> Seq Scan on status s1 (cost=0.00..1.44 rows=3 width=2)
(actual time=0.01..0.09 rows=4 loops=1)
-> Seq Scan on status s2 (cost=0.00..1.44 rows=3 width=2) (actual
time=0.01..0.07 rows=3 loops=3)
-> Hash
(cost=4.48..4.48 rows=96 width=34) (actual time=0.51..0.51 rows=0 loops=1)
->
Seq Scan on event_types (cost=0.00..4.48 rows=96 width=34) (actual time=0.05..0.36
rows=96 loops=1)
-> Hash
(cost=1.12..1.12 rows=1 width=25) (actual time=0.08..0.08 rows=0 loops=1)
-> Seq Scan
on event_cats (cost=0.00..1.12 rows=1 width=25) (actual time=0.06..0.07 rows=1
loops=1)
-> Sort (cost=1.61..1.61 rows=10
width=18) (actual time=0.49..0.51 rows=30 loops=1)
-> Seq Scan on status
(cost=0.00..1.52 rows=10 width=18) (actual time=0.05..0.14 rows=9 loops=1)
-> Index Scan using event_days_pk on event_days
(cost=0.00..3.96 rows=1 width=12) (actual time=0.05..0.05 rows=0 loops=26)
-> Index Scan using cases_pkey on cases
(cost=0.00..3.96 rows=1 width=61) (actual time=0.03..0.03 rows=0 loops=8)
-> Index Scan using trial_groups_pkey on trial_groups
(cost=0.00..3.49 rows=1 width=28) (actual time=0.02..0.02 rows=0 loops=8)
-> Seq Scan on opp_counsel (cost=0.00..2.44 rows=87 width=14)
(actual time=0.01..0.17 rows=87 loops=8)
-> Index Scan using events_pkey on events parent (cost=0.00..3.89
rows=1 width=44) (actual time=0.00..0.00 rows=0 loops=8)
-> Index Scan using events_pkey on events previous (cost=0.00..3.89 rows=1
width=44) (actual time=0.02..0.02 rows=0 loops=8)
SubPlan
-> Aggregate (cost=283.08..283.08 rows=1 width=23) (actual time=0.33..0.33
rows=1 loops=4)
-> Index Scan using idx_cases_tgroup on cases c1 (cost=0.00..283.05
rows=21 width=23) (actual time=0.08..0.23 rows=4 loops=4)
SubPlan
-> Index Scan using idx_caseclients_case on case_clients cc1
(cost=0.00..4.78 rows=1 width=7) (actual time=0.03..0.03 rows=1 loops=22)
Total runtime: 266463.54 msec
---------------------------(end of broadcast)---------------------------
TIP 1: subscribe and unsubscribe commands go to [EMAIL PROTECTED]
