Thread
-
Question about plan difference between 9.3 and 9.3.2
Jeff Ross <jross@openvistas.net> — 2014-01-17T17:54:00Z
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@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@dukkha:/var/www/stars/clearinghouse $ psql wykids psql (9.3.2) Type "help" for help. jross@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 -
Re: Question about plan difference between 9.3 and 9.3.2
Tom Lane <tgl@sss.pgh.pa.us> — 2014-01-17T18:02:30Z
Jeff Ross <jross@openvistas.net> writes: > 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. It looks like the newer server is not flattening the view before optimizing. Given that there's not that much distance between 9.3.0 and 9.3.2, I'd guess that the culprit must be this change: Author: Tom Lane <tgl@sss.pgh.pa.us> Branch: master [b97ee66cc] 2013-11-08 11:36:57 -0500 Branch: REL9_3_STABLE Release: REL9_3_2 [9548bee2b] 2013-11-08 11:37:00 -0500 Branch: REL9_2_STABLE Release: REL9_2_6 [f7171c7e2] 2013-11-08 11:37:04 -0500 Branch: REL9_1_STABLE Release: REL9_1_11 [af38d140c] 2013-11-08 11:37:08 -0500 Branch: REL9_0_STABLE Release: REL9_0_15 [987f05e16] 2013-11-08 11:37:12 -0500 Branch: REL8_4_STABLE Release: REL8_4_19 [90b07dd7b] 2013-11-08 11:37:17 -0500 Make contain_volatile_functions/contain_mutable_functions look into SubLinks. This change prevents us from doing inappropriate subquery flattening in cases such as dangerous functions hidden inside a sub-SELECT in the targetlist of another sub-SELECT. That could result in unexpected behavior due to multiple evaluations of a volatile function, as in a recent complaint from Etienne Dube. It's been questionable from the very beginning whether these functions should look into subqueries (as noted in their comments), and this case seems to provide proof that they should. Because the new code only descends into SubLinks, not SubPlans or InitPlans, the change only affects the planner's behavior during prepjointree processing and not later on --- for example, you can still get it to use a volatile function in an indexqual if you wrap the function in (SELECT ...). That's a historical behavior, for sure, but it's reasonable given that the executor's evaluation rules for subplans don't depend on whether there are volatile functions inside them. In any case, we need to constrain the behavioral change as narrowly as we can to make this reasonable to back-patch. You didn't show us the view, but is there a volatile function hidden inside a sub-select in its SELECT list? If so, can you safely change that function to stable or immutable marking? regards, tom lane -
Re: Question about plan difference between 9.3 and 9.3.2
Jeff Ross <jross@openvistas.net> — 2014-01-17T18:28:54Z
On 1/17/14, 11:02 AM, Tom Lane wrote: > Jeff Ross <jross@openvistas.net> writes: >> 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. > It looks like the newer server is not flattening the view before > optimizing. Given that there's not that much distance between 9.3.0 > and 9.3.2, I'd guess that the culprit must be this change: > > Author: Tom Lane <tgl@sss.pgh.pa.us> > Branch: master [b97ee66cc] 2013-11-08 11:36:57 -0500 > Branch: REL9_3_STABLE Release: REL9_3_2 [9548bee2b] 2013-11-08 11:37:00 -0500 > Branch: REL9_2_STABLE Release: REL9_2_6 [f7171c7e2] 2013-11-08 11:37:04 -0500 > Branch: REL9_1_STABLE Release: REL9_1_11 [af38d140c] 2013-11-08 11:37:08 -0500 > Branch: REL9_0_STABLE Release: REL9_0_15 [987f05e16] 2013-11-08 11:37:12 -0500 > Branch: REL8_4_STABLE Release: REL8_4_19 [90b07dd7b] 2013-11-08 11:37:17 -0500 > > Make contain_volatile_functions/contain_mutable_functions look into SubLinks. > > This change prevents us from doing inappropriate subquery flattening in > cases such as dangerous functions hidden inside a sub-SELECT in the > targetlist of another sub-SELECT. That could result in unexpected behavior > due to multiple evaluations of a volatile function, as in a recent > complaint from Etienne Dube. It's been questionable from the very > beginning whether these functions should look into subqueries (as noted in > their comments), and this case seems to provide proof that they should. > > Because the new code only descends into SubLinks, not SubPlans or > InitPlans, the change only affects the planner's behavior during > prepjointree processing and not later on --- for example, you can still get > it to use a volatile function in an indexqual if you wrap the function in > (SELECT ...). That's a historical behavior, for sure, but it's reasonable > given that the executor's evaluation rules for subplans don't depend on > whether there are volatile functions inside them. In any case, we need to > constrain the behavioral change as narrowly as we can to make this > reasonable to back-patch. > > You didn't show us the view, but is there a volatile function hidden > inside a sub-select in its SELECT list? If so, can you safely change > that function to stable or immutable marking? > > regards, tom lane > > Yes I did have a volatile function in that view and yes, changing it to immutable fixed the problem! Thanks, Tom! Jeff