SOLVED !!! Below is the new
EXPLAIN ANALYZE for 13.2 on AWS RDS (with no changes
to server parameters) along with the prior EXPLAIN ANALYZE outputs
for easy comparison.
While I didn't discount the significance & effect of optimizing the server parameters, this problem always seemed to me like a fundamental difference in how the PostgreSQL planner viewed the structure of the query. In particular, I had a usage pattern of writing VIEWS that worked very well with v9.6 & prior versions, but which made me suspect a route of attack:
Since the FCC tables contain lots of one-character codes for different conditions, to simplify maintenance & displays to humans, I created over twenty tiny lookup tables (a dozen or so entries in each table), to render a human-readable field as a replacement for the original one-character field in many of the VIEWs. In some cases those "humanized" fields were used as conditions in SELECT statements. Of course, fields that are not referenced or selected for output from a particular query, never get looked up (an advantage over using a JOIN for each lookup). In some cases, for ease of handling multiple or complex lookups, I indeed used a JOIN. All this worked fine until v10.
Here's the FROM clause that bit me:
FROM lic_en
JOIN govt_region USING (territory_id, country_id)
LEFT JOIN zip_code USING (territory_id, country_id, zip5)
LEFT JOIN "County" USING (territory_id, country_id, fips_county);
The first two JOINs are not the problem, & are in fact retained in my solution. The problem is the third JOIN, where "fips_county" from "County" is actually matched with the corresponding field from the "zip_code" VIEW. Works fine, if you don't mind the performance impact in v10 & above. It has now been rewritten, to be a sub-query for an output field. Voila ! Back to sub-second query times.
This also solved performance issues with other queries as well. I also now use lookup values as additional fields in the output, in addition to the original fields, which should help some more (but means some changes to some web pages that do queries).
-- Dean
ps: I wonder how many other RDS users of v9.6 are going to get a very rude awakening very soon, as AWS is not allowing new instances of v9.6 after August 2 (see https://forums.aws.amazon.com/ann.jspa?annID=8499 ). Whether that milestone affects restores from snapshots, remains to be seen (by others, not by me). In other words, users should plan to be up & running on a newer version well before August. Total cost to me? I"m in my 8th day of dealing with this, & I still have a number of web pages to update, due to changes in SQL field names to manage this mess. This was certainly not a obvious solution.
Here's from 13.2 (new):
=> EXPLAIN ANALYZE SELECT club_count, extra_count, region_count, callsign AS trustee_callsign, applicant_type, entity_name, licensee_id AS _lid FROM genclub_multi_ WHERE club_count >= 5 ORDER BY extra_count DESC, club_count DESC, entity_name;
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------
Sort (cost=457.77..457.77 rows=1 width=64) (actual time=48.737..48.742 rows=43 loops=1)
Sort Key: "_Club".extra_count DESC, "_Club".club_count DESC, "_EN".entity_name
Sort Method: quicksort Memory: 31kB
-> Nested Loop Left Join (cost=1.57..457.76 rows=1 width=64) (actual time=1.796..48.635 rows=43 loops=1)
-> Nested Loop (cost=1.28..457.07 rows=1 width=71) (actual time=1.736..48.239 rows=43 loops=1)
Join Filter: (("_EN".country_id = "_GovtRegion".country_id) AND ("_EN".state = "_GovtRegion".territory_id))
Rows Removed by Join Filter: 1297
-> Nested Loop (cost=1.28..453.75 rows=1 width=70) (actual time=1.720..47.778 rows=43 loops=1)
Join Filter: (("_HD".unique_system_identifier = "_EN".unique_system_identifier) AND ("_HD".callsign = "_EN".callsign))
-> Nested Loop (cost=0.85..450.98 rows=1 width=65) (actual time=1.207..34.912 rows=43 loops=1)
-> Nested Loop (cost=0.43..376.57 rows=27 width=50) (actual time=0.620..20.956 rows=43 loops=1)
-> Seq Scan on "_Club" (cost=0.00..4.44 rows=44 width=35) (actual time=0.037..0.067 rows=44 loops=1)
Filter: (club_count >= 5)
Rows Removed by Filter: 151
-> Index Scan using "_HD_callsign" on "_HD" (cost=0.43..8.45 rows=1 width=15) (actual time=0.474..0.474 rows=1 loops=44)
Index Cond: (callsign = "_Club".trustee_callsign)
Filter: (license_status = 'A'::bpchar)
Rows Removed by Filter: 0
-> Index Scan using "_AM_pkey" on "_AM" (cost=0.43..2.75 rows=1 width=15) (actual time=0.323..0.323 rows=1 loops=43)
Index Cond: (unique_system_identifier = "_HD".unique_system_identifier)
Filter: ("_HD".callsign = callsign)
-> Index Scan using "_EN_pkey" on "_EN" (cost=0.43..2.75 rows=1 width=60) (actual time=0.298..0.298 rows=1 loops=43)
Index Cond: (unique_system_identifier = "_AM".unique_system_identifier)
Filter: ("_AM".callsign = callsign)
-> Seq Scan on "_GovtRegion" (cost=0.00..1.93 rows=93 width=7) (actual time=0.002..0.004 rows=31 loops=43)
-> Nested Loop (cost=0.29..0.68 rows=1 width=7) (actual time=0.008..0.008 rows=1 loops=43)
-> Index Only Scan using "_IsoCountry_iso_alpha2_key" on "_IsoCountry" (cost=0.14..0.38 rows=1 width=3) (actual time=0.004..0.004 rows=1 loops=43)
Index Cond: (iso_alpha2 = "_GovtRegion".country_id)
Heap Fetches: 43
-> Index Only Scan using "_Territory_pkey" on "_Territory" (cost=0.14..0.29 rows=1 width=7) (actual time=0.003..0.003 rows=1 loops=43)
Index Cond: ((country_id = "_IsoCountry".iso_alpha2) AND (territory_id = "_GovtRegion".territory_id))
Heap Fetches: 43
Planning Time: 4.017 ms
Execution Time: 48.822 ms
On 2021-05-28 11:48, Dean Gibson (DB Administrator) wrote:
While I didn't discount the significance & effect of optimizing the server parameters, this problem always seemed to me like a fundamental difference in how the PostgreSQL planner viewed the structure of the query. In particular, I had a usage pattern of writing VIEWS that worked very well with v9.6 & prior versions, but which made me suspect a route of attack:
Since the FCC tables contain lots of one-character codes for different conditions, to simplify maintenance & displays to humans, I created over twenty tiny lookup tables (a dozen or so entries in each table), to render a human-readable field as a replacement for the original one-character field in many of the VIEWs. In some cases those "humanized" fields were used as conditions in SELECT statements. Of course, fields that are not referenced or selected for output from a particular query, never get looked up (an advantage over using a JOIN for each lookup). In some cases, for ease of handling multiple or complex lookups, I indeed used a JOIN. All this worked fine until v10.
Here's the FROM clause that bit me:
FROM lic_en
JOIN govt_region USING (territory_id, country_id)
LEFT JOIN zip_code USING (territory_id, country_id, zip5)
LEFT JOIN "County" USING (territory_id, country_id, fips_county);
The first two JOINs are not the problem, & are in fact retained in my solution. The problem is the third JOIN, where "fips_county" from "County" is actually matched with the corresponding field from the "zip_code" VIEW. Works fine, if you don't mind the performance impact in v10 & above. It has now been rewritten, to be a sub-query for an output field. Voila ! Back to sub-second query times.
This also solved performance issues with other queries as well. I also now use lookup values as additional fields in the output, in addition to the original fields, which should help some more (but means some changes to some web pages that do queries).
-- Dean
ps: I wonder how many other RDS users of v9.6 are going to get a very rude awakening very soon, as AWS is not allowing new instances of v9.6 after August 2 (see https://forums.aws.amazon.com/ann.jspa?annID=8499 ). Whether that milestone affects restores from snapshots, remains to be seen (by others, not by me). In other words, users should plan to be up & running on a newer version well before August. Total cost to me? I"m in my 8th day of dealing with this, & I still have a number of web pages to update, due to changes in SQL field names to manage this mess. This was certainly not a obvious solution.
Here's from 13.2 (new):
=> EXPLAIN ANALYZE SELECT club_count, extra_count, region_count, callsign AS trustee_callsign, applicant_type, entity_name, licensee_id AS _lid FROM genclub_multi_ WHERE club_count >= 5 ORDER BY extra_count DESC, club_count DESC, entity_name;
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------
Sort (cost=457.77..457.77 rows=1 width=64) (actual time=48.737..48.742 rows=43 loops=1)
Sort Key: "_Club".extra_count DESC, "_Club".club_count DESC, "_EN".entity_name
Sort Method: quicksort Memory: 31kB
-> Nested Loop Left Join (cost=1.57..457.76 rows=1 width=64) (actual time=1.796..48.635 rows=43 loops=1)
-> Nested Loop (cost=1.28..457.07 rows=1 width=71) (actual time=1.736..48.239 rows=43 loops=1)
Join Filter: (("_EN".country_id = "_GovtRegion".country_id) AND ("_EN".state = "_GovtRegion".territory_id))
Rows Removed by Join Filter: 1297
-> Nested Loop (cost=1.28..453.75 rows=1 width=70) (actual time=1.720..47.778 rows=43 loops=1)
Join Filter: (("_HD".unique_system_identifier = "_EN".unique_system_identifier) AND ("_HD".callsign = "_EN".callsign))
-> Nested Loop (cost=0.85..450.98 rows=1 width=65) (actual time=1.207..34.912 rows=43 loops=1)
-> Nested Loop (cost=0.43..376.57 rows=27 width=50) (actual time=0.620..20.956 rows=43 loops=1)
-> Seq Scan on "_Club" (cost=0.00..4.44 rows=44 width=35) (actual time=0.037..0.067 rows=44 loops=1)
Filter: (club_count >= 5)
Rows Removed by Filter: 151
-> Index Scan using "_HD_callsign" on "_HD" (cost=0.43..8.45 rows=1 width=15) (actual time=0.474..0.474 rows=1 loops=44)
Index Cond: (callsign = "_Club".trustee_callsign)
Filter: (license_status = 'A'::bpchar)
Rows Removed by Filter: 0
-> Index Scan using "_AM_pkey" on "_AM" (cost=0.43..2.75 rows=1 width=15) (actual time=0.323..0.323 rows=1 loops=43)
Index Cond: (unique_system_identifier = "_HD".unique_system_identifier)
Filter: ("_HD".callsign = callsign)
-> Index Scan using "_EN_pkey" on "_EN" (cost=0.43..2.75 rows=1 width=60) (actual time=0.298..0.298 rows=1 loops=43)
Index Cond: (unique_system_identifier = "_AM".unique_system_identifier)
Filter: ("_AM".callsign = callsign)
-> Seq Scan on "_GovtRegion" (cost=0.00..1.93 rows=93 width=7) (actual time=0.002..0.004 rows=31 loops=43)
-> Nested Loop (cost=0.29..0.68 rows=1 width=7) (actual time=0.008..0.008 rows=1 loops=43)
-> Index Only Scan using "_IsoCountry_iso_alpha2_key" on "_IsoCountry" (cost=0.14..0.38 rows=1 width=3) (actual time=0.004..0.004 rows=1 loops=43)
Index Cond: (iso_alpha2 = "_GovtRegion".country_id)
Heap Fetches: 43
-> Index Only Scan using "_Territory_pkey" on "_Territory" (cost=0.14..0.29 rows=1 width=7) (actual time=0.003..0.003 rows=1 loops=43)
Index Cond: ((country_id = "_IsoCountry".iso_alpha2) AND (territory_id = "_GovtRegion".territory_id))
Heap Fetches: 43
Planning Time: 4.017 ms
Execution Time: 48.822 ms
On 2021-05-28 11:48, Dean Gibson (DB Administrator) wrote:
...
Here's from v9.6:
=> EXPLAIN ANALYZE SELECT club_count, extra_count, region_count, callsign AS trustee_callsign, applicant_type, entity_name, licensee_id AS _lid FROM genclub_multi_ WHERE club_count >= 5 ORDER BY extra_count DESC, club_count DESC, entity_name;
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Sort (cost=407.13..407.13 rows=1 width=94) (actual time=348.850..348.859 rows=43 loops=1)
Sort Key: "_Club".extra_count DESC, "_Club".club_count DESC, "_EN".entity_name
Sort Method: quicksort Memory: 31kB
-> Nested Loop (cost=4.90..407.12 rows=1 width=94) (actual time=7.587..348.732 rows=43 loops=1)
-> Nested Loop (cost=4.47..394.66 rows=1 width=94) (actual time=5.740..248.149 rows=43 loops=1)
-> Nested Loop Left Join (cost=4.04..382.20 rows=1 width=79) (actual time=2.458..107.908 rows=55 loops=1)
-> Hash Join (cost=3.75..380.26 rows=1 width=86) (actual time=2.398..106.990 rows=55 loops=1)
Hash Cond: (("_EN".country_id = "_GovtRegion".country_id) AND ("_EN".state = "_GovtRegion".territory_id))
-> Nested Loop (cost=0.43..376.46 rows=47 width=94) (actual time=2.294..106.736 rows=55 loops=1)
-> Seq Scan on "_Club" (cost=0.00..4.44 rows=44 width=35) (actual time=0.024..0.101 rows=44 loops=1)
Filter: (club_count >= 5)
Rows Removed by Filter: 151
-> Index Scan using "_EN_callsign" on "_EN" (cost=0.43..8.45 rows=1 width=69) (actual time=2.179..2.420 rows=1 loops=44)
Index Cond: (callsign = "_Club".trustee_callsign)
-> Hash (cost=1.93..1.93 rows=93 width=7) (actual time=0.071..0.071 rows=88 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 12kB
-> Seq Scan on "_GovtRegion" (cost=0.00..1.93 rows=93 width=7) (actual time=0.010..0.034 rows=93 loops=1)
-> Nested Loop (cost=0.29..1.93 rows=1 width=7) (actual time=0.012..0.014 rows=1 loops=55)
Join Filter: ("_IsoCountry".iso_alpha2 = "_Territory".country_id)
Rows Removed by Join Filter: 0
-> Index Only Scan using "_IsoCountry_iso_alpha2_key" on "_IsoCountry" (cost=0.14..1.62 rows=1 width=3) (actual time=0.006..0.006 rows=1 loops=55)
Index Cond: (iso_alpha2 = "_GovtRegion".country_id)
Heap Fetches: 55
-> Index Only Scan using "_Territory_pkey" on "_Territory" (cost=0.14..0.29 rows=1 width=7)
(actual time=0.004..0.005 rows=1 loops=55)
Index Cond: (territory_id = "_GovtRegion".territory_id)
Heap Fetches: 59
-> Index Scan using "_HD_pkey" on "_HD" (cost=0.43..12.45 rows=1 width=15) (actual time=2.548..2.548 rows=1 loops=55)
Index Cond: (unique_system_identifier = "_EN".unique_system_identifier)
Filter: (("_EN".callsign = callsign) AND (((((license_status)::text || ' - '::text) || (COALESCE((SubPlan 2), '???'::character varying))::text))::character(1) = 'A'::bpchar))
Rows Removed by Filter: 0
SubPlan 2
-> Limit (cost=0.15..8.17 rows=1 width=32) (actual time=0.006..0.007 rows=1 loops=55)
-> Index Scan using "_LicStatus_pkey" on "_LicStatus" (cost=0.15..8.17 rows=1 width=32) (actual time=0.005..0.005 rows=1 loops=55)
Index Cond: ("_HD".license_status = status_id)
-> Index Scan using "_AM_pkey" on "_AM" (cost=0.43..4.27 rows=1 width=15) (actual time=2.325..2.325 rows=1 loops=43)
Index Cond: (unique_system_identifier = "_EN".unique_system_identifier)
Filter: ("_EN".callsign = callsign)
SubPlan 1
-> Limit (cost=0.15..8.17 rows=1 width=32) (actual time=0.007..0.007 rows=1 loops=43)
-> Index Scan using "_ApplicantType_pkey" on "_ApplicantType" (cost=0.15..8.17 rows=1 width=32) (actual time=0.005..0.005 rows=1 loops=43)
Index Cond: ("_EN".applicant_type_code = app_type_id)
Planning time: 13.490 ms
Execution time: 349.182 ms
(43 rows)
Here's from v13.2:
=> EXPLAIN ANALYZE SELECT club_count, extra_count, region_count, callsign AS trustee_callsign, applicant_type, entity_name, licensee_id AS _lid FROM genclub_multi_ WHERE club_count >= 5 ORDER BY extra_count DESC, club_count DESC, entity_name;
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Sort (cost=144365.60..144365.60 rows=1 width=94) (actual time=31898.860..31901.922 rows=43 loops=1)
Sort Key: "_Club".extra_count DESC, "_Club".club_count DESC, "_EN".entity_name
Sort Method: quicksort Memory: 31kB
-> Nested Loop (cost=58055.66..144365.59 rows=1 width=94) (actual time=6132.403..31894.233 rows=43 loops=1)
-> Nested Loop (cost=58055.51..144364.21 rows=1 width=62) (actual time=1226.085..30337.921 rows=837792 loops=1)
-> Nested Loop Left Join (cost=58055.09..144360.38 rows=1 width=59) (actual time=1062.414..12471.456 rows=1487153 loops=1)
-> Hash Join (cost=58054.80..144359.69 rows=1 width=66) (actual time=1061.330..6635.041 rows=1487153 loops=1)
Hash Cond: (("_EN".unique_system_identifier = "_AM".unique_system_identifier) AND ("_EN".callsign = "_AM".callsign))
-> Hash Join (cost=3.33..53349.72 rows=1033046 width=51) (actual time=2.151..3433.178 rows=1487153 loops=1)
Hash Cond: (("_EN".country_id = "_GovtRegion".country_id) AND ("_EN".state = "_GovtRegion".territory_id))
-> Seq Scan on "_EN" (cost=0.00..45288.05 rows=1509005 width=60) (actual time=0.037..2737.054 rows=1508736 loops=1)
-> Hash (cost=1.93..1.93 rows=93 width=7) (actual time=0.706..1.264 rows=88 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 12kB
-> Seq Scan on "_GovtRegion" (cost=0.00..1.93 rows=93 width=7) (actual time=0.013..0.577 rows=93 loops=1)
-> Hash (cost=28093.99..28093.99 rows=1506699 width=15) (actual time=1055.587..1055.588 rows=1506474 loops=1)
Buckets: 131072 Batches: 32 Memory Usage: 3175kB
-> Seq Scan on "_AM" (cost=0.00..28093.99 rows=1506699 width=15) (actual time=0.009..742.774 rows=1506474 loops=1)
-> Nested Loop (cost=0.29..0.68 rows=1 width=7) (actual time=0.003..0.004 rows=1 loops=1487153)
Join Filter: ("_IsoCountry".iso_alpha2 = "_Territory".country_id)
Rows Removed by Join Filter: 0
-> Index Only Scan using "_IsoCountry_iso_alpha2_key" on "_IsoCountry" (cost=0.14..0.38 rows=1 width=3) (actual time=0.001..0.002 rows=1 loops=1487153)
Index Cond: (iso_alpha2 = "_GovtRegion".country_id)
Heap Fetches: 1487153
-> Index Only Scan using "_Territory_pkey" on "_Territory" (cost=0.14..0.29 rows=1 width=7) (actual time=0.001..0.001 rows=1 loops=1487153)
Index Cond: (territory_id = "_GovtRegion".territory_id)
Heap Fetches: 1550706
-> Index Scan using "_HD_pkey" on "_HD" (cost=0.43..3.82 rows=1 width=15) (actual time=0.012..0.012 rows=1 loops=1487153)
Index Cond: (unique_system_identifier = "_EN".unique_system_identifier)
Filter: (("_EN".callsign = callsign) AND (((((license_status)::text || ' - '::text) || (COALESCE((SubPlan 2), '???'::character varying))::text))::character(1) = 'A'::bpchar))
Rows Removed by Filter: 0
SubPlan 2
-> Limit (cost=0.00..1.07 rows=1 width=13) (actual time=0.001..0.001 rows=1 loops=1487153)
-> Seq Scan on "_LicStatus" (cost=0.00..1.07 rows=1 width=13) (actual time=0.000..0.000 rows=1 loops=1487153)
Filter: ("_HD".license_status = status_id)
Rows Removed by Filter: 1
-> Index Scan using "_Club_pkey" on "_Club" (cost=0.14..0.17 rows=1 width=35) (actual time=0.002..0.002 rows=0 loops=837792)
Index Cond: (trustee_callsign = "_EN".callsign)
Filter: (club_count >= 5)
Rows Removed by Filter: 0
SubPlan 1
-> Limit (cost=0.00..1.20 rows=1 width=15) (actual time=0.060..0.060 rows=1 loops=43)
-> Seq Scan on "_ApplicantType" (cost=0.00..1.20 rows=1 width=15) (actual time=0.016..0.016 rows=1 loops=43)
Filter: ("_EN".applicant_type_code = app_type_id)
Rows Removed by Filter: 7
Planning Time: 173.753 ms
Execution Time: 31919.601 ms
(46 rows)
