Question about plan difference between 9.3 and 9.3.2

Hi all,

I had to move our production database to a new server with virtually
identical hardware. At the same time I went to 9.3.2 from 9.3.

Queries on the old server (nirvana) run many magnitudes faster than on
the new server (dukkha).

The two are configured the same except for the IP address to listen on.

Here's an example of the difference between the old and new.

_postgresql(at)nirvana:/var/postgresql $ psql wykids
psql (9.3.0)
Type "help" for help.

wykids=# explain analyze select pp_full_name from view_person where
pp_id = 21058;
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------
Index Scan using people_pk on people (cost=0.29..8.37 rows=1
width=30) (actual time=0.101..0.107 rows=1 loops=1)
Index Cond: (pp_id = 21058)
Total runtime: 0.308 ms
(3 rows)

jross(at)dukkha:/var/www/stars/clearinghouse $ psql wykids
psql (9.3.2)
Type "help" for help.

jross(at)wykids dukkha# explain analyze select pp_full_name from
view_person where pp_id = 21058;
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Subquery Scan on view_person (cost=0.29..321.63 rows=1 width=32)
(actual time=4.756..4.770 rows=1 loops=1)
-> Index Scan using people_pk on people (cost=0.29..321.58 rows=1
width=492) (actual time=4.747..4.753 rows=1 loops=1)
Index Cond: (pp_id = 21058)
SubPlan 1
-> Nested Loop Left Join (cost=0.57..16.73 rows=1
width=15) (actual time=0.107..0.107 rows=0 loops=1)
-> Index Scan using no_duplicate_people_ids on
providers (cost=0.29..8.35 rows=1 width=4) (actual time=0.094..0.094
rows=0 loops=1)
Index Cond: (pv_people_id = people.pp_id)
Filter: ((pv_facility_id IS NOT NULL) AND
((pv_status)::text = 'Active'::text))
Rows Removed by Filter: 1
-> Index Scan using facilities_pkey on facilities
(cost=0.28..8.34 rows=1 width=19) (never executed)
Index Cond: (providers.pv_facility_id =
fc_facility_id)
SubPlan 2
-> Nested Loop Left Join (cost=0.57..16.73 rows=1 width=8)
(actual time=0.021..0.021 rows=0 loops=1)
-> Index Scan using no_duplicate_people_ids on
providers providers_1 (cost=0.29..8.35 rows=1 width=4) (actual
time=0.012..0.012 rows=0 loops=1)
Index Cond: (pv_people_id = people.pp_id)
Filter: ((pv_facility_id IS NOT NULL) AND
((pv_status)::text = 'Active'::text))
Rows Removed by Filter: 1
-> Index Scan using facilities_pkey on facilities
facilities_1 (cost=0.28..8.34 rows=1 width=12) (never executed)
Index Cond: (providers_1.pv_facility_id =
fc_facility_id)
SubPlan 3
-> Nested Loop Left Join (cost=0.57..16.73 rows=1 width=3)
(actual time=0.021..0.021 rows=0 loops=1)
-> Index Scan using no_duplicate_people_ids on
providers providers_2 (cost=0.29..8.35 rows=1 width=4) (actual
time=0.011..0.011 rows=0 loops=1)
Index Cond: (pv_people_id = people.pp_id)
Filter: ((pv_facility_id IS NOT NULL) AND
((pv_status)::text = 'Active'::text))
Rows Removed by Filter: 1
-> Index Scan using facilities_pkey on facilities
facilities_2 (cost=0.28..8.34 rows=1 width=7) (never executed)
Index Cond: (providers_2.pv_facility_id =
fc_facility_id)
SubPlan 4
-> Nested Loop Left Join (cost=0.57..16.73 rows=1 width=6)
(actual time=0.020..0.020 rows=0 loops=1)
-> Index Scan using no_duplicate_people_ids on
providers providers_3 (cost=0.29..8.35 rows=1 width=4) (actual
time=0.011..0.011 rows=0 loops=1)
Index Cond: (pv_people_id = people.pp_id)
Filter: ((pv_facility_id IS NOT NULL) AND
((pv_status)::text = 'Active'::text))
Rows Removed by Filter: 1
-> Index Scan using facilities_pkey on facilities
facilities_3 (cost=0.28..8.34 rows=1 width=10) (never executed)
Index Cond: (providers_3.pv_facility_id =
fc_facility_id)
SubPlan 5
-> Index Only Scan using pne_no_duplicates on
people_no_email (cost=0.14..4.20 rows=1 width=4) (actual
time=0.017..0.017 rows=0 loops=1)
Index Cond: (pne_pp_id = people.pp_id)
Heap Fetches: 0
SubPlan 6
-> Index Only Scan using pne_no_duplicates on
people_no_email people_no_email_1 (cost=0.14..4.20 rows=1 width=4)
(actual time=0.007..0.007 rows=0 loops=1)
Index Cond: (pne_pp_id = people.pp_id)
Heap Fetches: 0
SubPlan 7
-> Aggregate (cost=46.62..46.67 rows=1 width=0) (actual
time=0.079..0.082 rows=1 loops=1)
-> Index Scan using ck_people_id_idx on
clearinghouse_checkout (cost=0.29..46.61 rows=1 width=0) (actual
time=0.025..0.025 rows=0 loops=1)
Index Cond: (ck_people_id = people.pp_id)
Filter: ((ck_return_date IS NULL) AND
(ck_due_date < ('now'::cstring)::date))
SubPlan 8
-> Sort (cost=8.34..8.35 rows=1 width=11) (actual
time=0.182..0.182 rows=0 loops=1)
Sort Key: people_previous_last_name.ppln_date_recorded
Sort Method: quicksort Memory: 17kB
-> Index Scan using
people_previous_last_name_ppln_pp_id_idx on people_previous_last_name
(cost=0.28..8.33 rows=1 width=11) (actual time=0.034..0.034 rows=0 loops=1)
Index Cond: (ppln_pp_id = people.pp_id)
SubPlan 9
-> Index Scan using pp_race_cat_pp_id_idx on
people_race_categories (cost=0.28..8.34 rows=1 width=4) (actual
time=0.065..0.065 rows=0 loops=1)
Index Cond: (people.pp_id = pp_race_cat_pp_id)
Filter: (pp_race_cat_id = 1)
Rows Removed by Filter: 1
SubPlan 10
-> Index Scan using pp_race_cat_pp_id_idx on
people_race_categories people_race_categories_1 (cost=0.28..8.34 rows=1
width=4) (actual time=0.014..0.014 rows=0 loops=1)
Index Cond: (people.pp_id = pp_race_cat_pp_id)
Filter: (pp_race_cat_id = 2)
Rows Removed by Filter: 1
SubPlan 11
-> Index Scan using pp_race_cat_pp_id_idx on
people_race_categories people_race_categories_2 (cost=0.28..8.34 rows=1
width=4) (actual time=0.013..0.013 rows=0 loops=1)
Index Cond: (people.pp_id = pp_race_cat_pp_id)
Filter: (pp_race_cat_id = 3)
Rows Removed by Filter: 1
SubPlan 12
-> Index Scan using pp_race_cat_pp_id_idx on
people_race_categories people_race_categories_3 (cost=0.28..8.34 rows=1
width=4) (actual time=0.013..0.013 rows=0 loops=1)
Index Cond: (people.pp_id = pp_race_cat_pp_id)
Filter: (pp_race_cat_id = 4)
Rows Removed by Filter: 1
SubPlan 13
-> Index Scan using pp_race_cat_pp_id_idx on
people_race_categories people_race_categories_4 (cost=0.28..8.34 rows=1
width=4) (actual time=0.013..0.017 rows=1 loops=1)
Index Cond: (people.pp_id = pp_race_cat_pp_id)
Filter: (pp_race_cat_id = 5)
SubPlan 14
-> Index Scan using pp_ethnic_cat_pp_id_idx on
people_ethnic_categories (cost=0.29..8.35 rows=1 width=4) (actual
time=0.056..0.056 rows=0 loops=1)
Index Cond: (people.pp_id = pp_ethnic_cat_pp_id)
Filter: (pp_ethnic_cat_id = 1)
Rows Removed by Filter: 1
SubPlan 15
-> Index Scan using pp_ethnic_cat_pp_id_idx on
people_ethnic_categories people_ethnic_categories_1 (cost=0.29..8.35
rows=1 width=4) (actual time=0.012..0.017 rows=1 loops=1)
Index Cond: (people.pp_id = pp_ethnic_cat_pp_id)
Filter: (pp_ethnic_cat_id = 2)
SubPlan 16
-> Hash Join (cost=8.39..12.29 rows=1 width=8) (actual
time=0.228..0.522 rows=1 loops=1)
Hash Cond: (languages.lang_id =
people_primary_language.ppl_lang_id)
-> Seq Scan on languages (cost=0.00..3.65 rows=53
width=12) (actual time=0.009..0.190 rows=53 loops=1)
-> Hash (cost=8.34..8.34 rows=1 width=4) (actual
time=0.068..0.068 rows=1 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 1kB
-> Index Scan using ppl_pp_id_idx on
people_primary_language (cost=0.28..8.34 rows=1 width=4) (actual
time=0.048..0.053 rows=1 loops=1)
Index Cond: (people.pp_id = ppl_pp_id)
SubPlan 17
-> Hash Join (cost=8.26..12.16 rows=1 width=8) (actual
time=0.109..0.109 rows=0 loops=1)
Hash Cond: (languages_1.lang_id =
people_secondary_language.psl_lang_id)
-> Seq Scan on languages languages_1 (cost=0.00..3.65
rows=53 width=12) (actual time=0.006..0.006 rows=1 loops=1)
-> Hash (cost=8.21..8.21 rows=1 width=4) (actual
time=0.028..0.028 rows=0 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 0kB
-> Index Scan using psl_pp_id_idx on
people_secondary_language (cost=0.15..8.21 rows=1 width=4) (actual
time=0.018..0.018 rows=0 loops=1)
Index Cond: (people.pp_id = psl_pp_id)
SubPlan 18
-> Limit (cost=4.80..4.81 rows=1 width=12) (actual
time=0.145..0.145 rows=0 loops=1)
-> Sort (cost=4.80..4.81 rows=1 width=12) (actual
time=0.137..0.137 rows=0 loops=1)
Sort Key:
people_accreditation_categories.pp_acc_date_recorded
Sort Method: quicksort Memory: 17kB
-> Seq Scan on people_accreditation_categories
(cost=0.00..4.79 rows=1 width=12) (actual time=0.030..0.030 rows=0 loops=1)
Filter: ((people.pp_id = pp_acc_pp_id) AND
(pp_acc_cat_id = 1))
Rows Removed by Filter: 69
SubPlan 19
-> Limit (cost=4.80..4.81 rows=1 width=12) (actual
time=0.071..0.071 rows=0 loops=1)
-> Sort (cost=4.80..4.81 rows=1 width=12) (actual
time=0.063..0.063 rows=0 loops=1)
Sort Key:
people_accreditation_categories_1.pp_acc_date_recorded
Sort Method: quicksort Memory: 17kB
-> Seq Scan on people_accreditation_categories
people_accreditation_categories_1 (cost=0.00..4.79 rows=1 width=12)
(actual time=0.027..0.027 rows=0 loops=1)
Filter: ((people.pp_id = pp_acc_pp_id) AND
(pp_acc_cat_id = 2))
Rows Removed by Filter: 69
SubPlan 20
-> Index Only Scan using pla_pp_id_idx on
people_locked_accounts (cost=0.14..4.20 rows=1 width=4) (actual
time=0.010..0.010 rows=0 loops=1)
Index Cond: (pla_pp_id = people.pp_id)
Heap Fetches: 0
SubPlan 21
-> Index Scan using pla_pp_id_idx on people_locked_accounts
people_locked_accounts_1 (cost=0.14..8.20 rows=1 width=34) (actual
time=0.007..0.007 rows=0 loops=1)
Index Cond: (people.pp_id = pla_pp_id)
SubPlan 22
-> Index Scan using pla_pp_id_idx on people_locked_accounts
people_locked_accounts_2 (cost=0.14..8.20 rows=1 width=4) (actual
time=0.006..0.006 rows=0 loops=1)
Index Cond: (people.pp_id = pla_pp_id)
SubPlan 23
-> Index Scan using pla_pp_id_idx on people_locked_accounts
people_locked_accounts_3 (cost=0.14..8.20 rows=1 width=5) (actual
time=0.007..0.007 rows=0 loops=1)
Index Cond: (people.pp_id = pla_pp_id)
SubPlan 26
-> Result (cost=61.44..61.49 rows=1 width=0) (actual
time=2.747..2.751 rows=1 loops=1)
InitPlan 25 (returns $29)
-> Nested Loop (cost=51.83..61.44 rows=1 width=66)
(actual time=2.709..2.730 rows=1 loops=1)
InitPlan 24 (returns $28)
-> Aggregate (cost=51.50..51.55 rows=1
width=4) (actual time=2.574..2.577 rows=1 loops=1)
-> Function Scan on education
(cost=0.25..50.25 rows=500 width=4) (actual time=2.507..2.535 rows=7
loops=1)
Filter: has_earned
Rows Removed by Filter: 2
-> Index Scan using pp_ed_cat_pp_id_idx on
people_education_categories (cost=0.29..8.35 rows=1 width=55) (actual
time=2.652..2.657 rows=1 loops=1)
Index Cond: (pp_ed_cat_pp_id = people.pp_id)
Filter: (pp_ed_cat_id = $28)
Rows Removed by Filter: 6
-> Seq Scan on education_categories
(cost=0.00..1.47 rows=1 width=19) (actual time=0.011..0.016 rows=1 loops=1)
Filter: (ed_cat_id = $28)
Rows Removed by Filter: 8
Total runtime: 8.645 ms
(149 rows)

I asked about this on IRC and was told that there were a lot of planner
improvements in 9.3.2 but this kind of slowdown can't be an improvement.

I ran the slow query through explain.depesz.com--the result is here.

http://explain.depesz.com/s/fiHh

More complex queries that run in a couple hundred ms on the old server
are taking about 9 seconds to complete on the new server, and postgres
is using 90+% of cpu for the entire time. I've vacuumed analyzed the
new server but that didn't seem to make a difference.

Thanks for any insight!

Jeff Ross