Hi,
We're currently testing out upgrade of our Postgres database from 9.3.14 to 9.4.9. We are using Amazon RDS. We've encountered an issue in testing phase where after the upgrade, CPU utilization hovers around 100%. We dug deep to find that the queries which executed in a few milliseconds on Postgres 9.3.14 are taking a lot of time to complete on 9.4.9. We've noticed a pattern under which the query planner (in almost all queries) is using primary key index for scanning the table while ignoring other alternatives like explicit sorting or using another efficient index present on the table.
I'm sharing a few queries along with the query plans of Postgres 9.3 and 9.4.
1. First Query:
EXPLAIN ANALYZE SELECT user_device_identifiers.id as user_device_identifier_id, device_identifiers.partner_id as partner_id FROM user_device_identifiers INNER JOIN device_identifiers ON device_identifiers.id = user_device_identifiers.device_identifier_id WHERE (user_device_identifiers.status = 1 AND user_device_identifiers.authentication_token = '2y_mHHruh69pPpNo2GFn') ORDER BY user_device_identifiers.id ASC LIMIT 1;
Query plan of Postgres 9.3:
Limit (cost=17.06..17.06 rows=1 width=8) (actual time=5.654..5.655 rows=1 loops=1)
-> Sort (cost=17.06..17.06 rows=1 width=8) (actual time=5.653..5.653 rows=1 loops=1)
Sort Key: user_device_identifiers.id
Sort Method: quicksort Memory: 25kB
-> Nested Loop (cost=1.00..17.05 rows=1 width=8) (actual time=5.637..5.640 rows=1 loops=1)
-> Index Scan using index_user_device_identifiers_on_authentication_token on user_device_identifiers (cost=0.56..8.58 rows=1 width=8) (actual time=3.114..3.114 rows=1 loops=1)
Index Cond: ((authentication_token)::text = '2y_mHHruh69pPpNo2GFn'::text)
Filter: (status = 1)
-> Index Scan using device_identifiers_pkey on device_identifiers (cost=0.43..8.46 rows=1 width=8) (actual time=2.519..2.520 rows=1 loops=1)
Index Cond: (id = user_device_identifiers.device_identifier_id)
Total runtime: 5.686 ms
(11 rows)
Query plan of Postgres 9.4:
Limit (cost=0.87..4181.94 rows=1 width=8) (actual time=93014.991..93014.992 rows=1 loops=1)
-> Nested Loop (cost=0.87..1551177.78 rows=371 width=8) (actual time=93014.990..93014.990 rows=1 loops=1)
-> Index Scan using a_pkey on a (cost=0.43..1548042.20 rows=371 width=8) (actual time=93014.968..93014.968 rows=1 loops=1)
Filter: ((col_int = 1) AND ((col_text)::text = 'pqrs'::text))
Rows Removed by Filter: 16114217
-> Index Scan using b_pkey on b (cost=0.43..8.44 rows=1 width=8) (actual time=0.014..0.014 rows=1 loops=1)
Index Cond: (id = a.b_id)
Planning time: 0.291 ms
Execution time: 93015.041 ms
2nd Query:
EXPLAIN ANALYZE SELECT hotels.id FROM hotels INNER JOIN hotel_restrictions ON hotel_restrictions.hotel_id = hotels.id INNER JOIN restrictions ON restrictions.id = hotel_restrictions.restriction_id WHERE (hotel_restrictions.status = 1) AND restrictions.id = 12 AND (((hotel_restrictions.from_time < '2018-01-10' and hotel_restrictions.to_time >='2018-01-09') OR (hotel_restrictions.from_time is null AND hotel_restrictions.to_time is null)) and (not (excluded_days @> (select array((select distinct extract (dow from generate_series(case when '2018-01-09'::date > hotel_restrictions.from_time then '2018-01-09'::date else hotel_restrictions.from_time end,case when '2018-01-10'::date <= hotel_restrictions.to_time then '2018-01-09'::date else hotel_restrictions.to_time end,'1 day'::interval))::integer)))) or excluded_days is null));
Query plan of Postgres 9.3:
Nested Loop (cost=26828.12..138106.67 rows=6597 width=4) (actual time=52.956..157.053 rows=4972 loops=1)
-> Seq Scan on restrictions (cost=0.00..1.56 rows=1 width=4) (actual time=0.007..0.014 rows=1 loops=1)
Filter: (id = 12)
Rows Removed by Filter: 44
-> Nested Loop (cost=26828.12..138039.14 rows=6597 width=8) (actual time=52.947..154.531 rows=4972 loops=1)
-> Bitmap Heap Scan on hotel_restrictions (cost=26827.70..130501.88 rows=6597 width=8) (actual time=52.932..120.653 rows=4972 loops=1)
Recheck Cond: (((to_time >= '2018-01-09'::date) AND (restriction_id = 12) AND (from_time < '2018-01-10'::date) AND (status = 1)) OR ((to_time IS NULL) AND (restriction_id = 12) AND (from_time IS NULL) AND (status = 1)))
Filter: ((NOT (excluded_days @> (SubPlan 2))) OR (excluded_days IS NULL))
Rows Removed by Filter: 359
-> BitmapOr (cost=26827.70..26827.70 rows=6600 width=0) (actual time=52.253..52.253 rows=0 loops=1)
-> Bitmap Index Scan on hotel_restrictions_multi_column_index (cost=0.00..26819.67 rows=6580 width=0) (actual time=52.242..52.242 rows=5568 loops=1)
Index Cond: ((to_time >= '2018-01-09'::date) AND (restriction_id = 12) AND (from_time < '2018-01-10'::date) AND (status = 1))
-> Bitmap Index Scan on hotel_restrictions_multi_column_index (cost=0.00..4.73 rows=20 width=0) (actual time=0.009..0.009 rows=0 loops=1)
Index Cond: ((to_time IS NULL) AND (restriction_id = 12) AND (from_time IS NULL) AND (status = 1))
SubPlan 2
-> Result (cost=12.54..12.55 rows=1 width=0) (actual time=0.009..0.009 rows=1 loops=5331)
InitPlan 1 (returns $2)
-> HashAggregate (cost=7.52..12.54 rows=1000 width=0) (actual time=0.006..0.006 rows=1 loops=5331)
-> Result (cost=0.00..5.02 rows=1000 width=0) (actual time=0.003..0.004 rows=1 loops=5331)
-> Index Only Scan using hotels_pkey on hotels (cost=0.41..1.13 rows=1 width=4) (actual time=0.005..0.005 rows=1 loops=4972)
Index Cond: (id = hotel_restrictions.hotel_id)
Heap Fetches: 2336
Total runtime: 158.571 ms
(23 rows)
Query plan of Postgres 9.4:
Nested Loop (cost=593.29..625.92 rows=1 width=4) (actual time=207.395..581946.198 rows=4928 loops=1)
-> Nested Loop (cost=593.14..617.75 rows=1 width=8) (actual time=207.385..581591.597 rows=4928 loops=1)
-> Index Only Scan using hotels_pkey on hotels (cost=0.38..8.39 rows=1 width=4)
(actual time=0.012..315.263 rows=16197 loops=1)
Heap Fetches: 3062
-> Bitmap Heap Scan on hotel_restrictions (cost=592.77..609.35 rows=1 width=8)
(actual time=35.845..35.852 rows=0 loops=16197)
Recheck Cond: ((restriction_id = 12) AND (status = 1) AND (hotel_id = hotel
s.id))
Filter: ((((from_time < '2018-01-10'::date) AND (to_time >= '2018-01-09'::date)) OR ((from_time IS NULL) AND (to_time IS NULL))) AND ((NOT (excluded_days @> (SubPlan
2))) OR (excluded_days IS NULL)))
Rows Removed by Filter: 2
Heap Blocks: exact=33625
-> BitmapAnd (cost=592.77..592.77 rows=1 width=0) (actual time=35.626..35.626 rows=0 loops=16197)
-> Bitmap Index Scan on hotel_restrictions_multi_column_status_restriction_id_index (cost=0.00..5.78 rows=135 width=0) (actual time=30.129..30.129 rows=43908
loops=16197)
Index Cond: ((restriction_id = 12) AND (status = 1))
-> Bitmap Index Scan on index_hotel_restrictions_on_hotel_id (cost=0.00..586.73 rows=26973 width=0) (actual time=0.223..0.223 rows=290 loops=16197)
Index Cond: (hotel_id = hotels.id)
SubPlan 2
-> Result (cost=12.54..12.55 rows=1 width=0) (actual time=0.087..0.087 rows=1 loops=5290)
InitPlan 1 (returns $2)
-> HashAggregate (cost=7.52..12.54 rows=1000 width=0) (actual time=0.036..0.036 rows=1 loops=5290)
Group Key: (date_part('dow'::text, generate_series((CASE WHEN ('2018-01-09'::date > hotel_restrictions.from_time) THEN '2018-01-09'::date ELSE hotel_r
estrictions.from_time END)::timestamp with time zone, (CASE WHEN ('2018-01-10'::date <= hotel_restrictions.to_time) THEN '2018-01-09'::date ELSE hotel_restrictions.to_time END)::tim
estamp with time zone, '1 day'::interval)))::integer
-> Result (cost=0.00..5.02 rows=1000 width=0) (actual time=0.018..0.019 rows=1 loops=5290)
-> Index Only Scan using restrictions_pkey on restrictions (cost=0.14..8.16 rows=1 width=4) (actual time=0.056..0.057 rows=1 loops=4928)
Index Cond: (id = 12)
Heap Fetches: 0
Planning time: 0.716 ms
Execution time: 581961.388 ms
3. Query 3
EXPLAIN ANALYZE SELECT referral_aliases.* FROM referral_aliases WHERE referral_aliases.user_id = 651659 AND (meta_data ->> 'type' = 'phase_4') ORDER BYreferral_aliases.id DESC LIMIT 1;
Query plan of Postgres 9.3:
Limit (cost=10.37..10.37 rows=1 width=71) (actual time=0.035..0.035 rows=1 loops=1)
-> Sort (cost=10.37..10.37 rows=1 width=71) (actual time=0.035..0.035 rows=1 loops=1)
Sort Key: id
Sort Method: quicksort Memory: 25kB
-> Index Scan using rahul_temp_refalias on referral_aliases (cost=0.43..10.36 rows=1 width=71) (actual time=0.025..0.026 rows=1 loops=1)
Index Cond: (user_id = 651659)
Filter: ((meta_data ->> 'type'::text) = 'phase_4'::text)
Total runtime: 0.064 ms
(8 rows)
Query plan of Postgres 9.4:
Limit (cost=0.44..3669.38 rows=1 width=93) (actual time=26581.387..26581.388 rows=1 loops=1)
-> Index Scan Backward using referral_aliases_pkey on referral_aliases (cost=0.44..1794114.76 rows=489 width=93) (actual time=26581.384..26581.384 rows=1 loops=1)
Filter: ((user_id = 651659) AND ((meta_data ->> 'type'::text) = 'phase_4'::text))
Rows Removed by Filter: 8574282
Planning time: 0.127 ms
Execution time: 26581.418 ms
(6 rows)
We've tried tweaking several parameters like effective_cache, enable_indexscan, enable_indexonlyscan, enable_seqscan, but to no results. We've also checked that the enable_sort parameter is on in our parameter group. We also tried doing full vacuum on the tables used in above queries.
Could you please suggest something so that we can get Postgres 9.4 to change it's query plan in these cases?
Thanks,
Rahul
