On 10/1/22 14:54, Christoph Moench-Tegeder wrote:
## Ron (ronljohnsonjr@xxxxxxxxx):The question then is "why am I just now seeing the problem?" We've been using v12 for two years, and it just happened. The only recent change is that I upgraded it from RDS 12.10 to 12.11 a couple of weeks ago.That's correlation, but no proof for causality.
Right. But it is an important change which happened between job runs (the 22nd of each month).
Now that you've confirmed that you have indeed a mismatch between generic and custom plan, you could compare those (EXPLAIN EXECUTE) and see where the generic plan goes wrong.
I'll rerun the EXPLAIN EXECUTE with and without "plan_cache_mode = force_custom_plan", and attach them in a reply some time soon.
Attached are explain outputs from: , and then
TASK001785639_explain_output_custom.log: a "first five" fast execution
TASK001785639_explain_output_generic.log: "the sixth" (generic) plan when it took 6 minutes.
Next are similar plans except where default_statistic_target = 1000, and the table is reanalyzed. It didn't help with this query.
TASK001785639_explain_output_custom_def_stats_1000.log
TASK001785639_explain_output_generic_def_stats_1000.log
Finally is the explain output from "plan_cache_mode = force_custom_plan":
TASK001785639_explain_output_force_custom_def_stats_1000.log
According to meld diff, custom_def_stats_1000 and force_custom_def_stats_1000 have surprisingly similar plans (the only difference being that in the forced custom plan, 2 workers were launched, and so they filtered out some rows. Execution time was about 460ms in both.
[snip]
If would help if you could compare execution plans with plans from before the update, but I guess you didn't document those?
So, since ANALYZE did not help.
EDIT: No, since ANALYZE did not help.
--
Angular momentum makes the world go 'round.
Angular momentum makes the world go 'round.
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=176420.04..176420.05 rows=1 width=8) (actual time=457.035..457.974 rows=1 loops=1)
-> Gather (cost=120083.10..176417.85 rows=125 width=45) (actual time=311.639..457.225 rows=499 loops=1)
Workers Planned: 2
Workers Launched: 2
-> Parallel Hash Anti Join (cost=119083.10..175405.35 rows=52 width=45) (actual time=309.084..452.471 rows=166 loops=3)
Hash Cond: ((sire.reqte_endpoint_id = sire2.reqte_endpoint_id) AND (sire.reqtde_endpoint_id = sire2.reqtde_endpoint_id) AND ((sire.record_guid)::text = (sire2.record_guid)::text))
Join Filter: ((sire2.separation_request_id <> sire.separation_request_id) AND (sire2.reqt_processing_completed_dts < sire.reqt_processing_completed_dts))
Rows Removed by Join Filter: 167
-> Parallel Index Scan using xif11sep_info_report_extract on sep_info_report_extract sire (cost=0.56..56321.62 rows=52 width=60) (actual time=1.275..144.492 rows=166 loops=3)
Index Cond: ((reqt_processing_completed_dts >= '2022-08-01 00:00:00'::timestamp without time zone) AND (reqt_processing_completed_dts <= '2022-08-31 23:59:59'::timestamp without time zone))
Filter: (((reqt_failed_ind)::text <> '1'::text) AND ((reqxt_failed_ind IS NULL) OR ((reqxt_failed_ind)::text <> '1'::text)) AND ((resxt_failed_ind IS NULL) OR ((resxt_failed_ind)::text <> '1'::text)) AND ((reqtde_organization_type)::text <> 'SEW_EMPLOYER'::text) AND (req_valid_ind = '1'::numeric) AND (reqte_endpoint_id = '1'::numeric(38,0)) AND (reqtde_endpoint_id = '507650'::numeric(38,0)) AND (((res_valid_ind = '1'::numeric) AND ((rest_failed_ind)::text <> '1'::text)) OR ((res_valid_ind IS NULL) AND (rest_failed_ind IS NULL))) AND ((rest_processing_completed_dts IS NOT NULL) OR (response_due_date < date_trunc('day'::text, timezone('America/New_York'::text, clock_timestamp())))))
Rows Removed by Filter: 162390
-> Parallel Hash (cost=119080.39..119080.39 rows=123 width=60) (actual time=307.693..307.694 rows=364 loops=3)
Buckets: 1024 Batches: 1 Memory Usage: 168kB
-> Parallel Index Scan using xif11sep_info_report_extract on sep_info_report_extract sire2 (cost=0.56..119080.39 rows=123 width=60) (actual time=1.656..307.415 rows=364 loops=3)
Index Cond: ((reqt_processing_completed_dts >= '2022-06-27 00:00:00'::timestamp without time zone) AND (reqt_processing_completed_dts <= '2022-08-31 23:59:59'::timestamp without time zone))
Filter: ((rest_processing_completed_dts IS NOT NULL) AND ((reqt_failed_ind)::text <> '1'::text) AND ((reqxt_failed_ind IS NULL) OR ((reqxt_failed_ind)::text <> '1'::text)) AND ((rest_failed_ind)::text <> '1'::text) AND ((reqtde_organization_type)::text <> 'SEW_EMPLOYER'::text) AND (req_valid_ind = '1'::numeric) AND (res_valid_ind = '1'::numeric) AND (reqte_endpoint_id = '1'::numeric(38,0)) AND (reqtde_endpoint_id = '507650'::numeric(38,0)))
Rows Removed by Filter: 358336
Planning Time: 0.966 ms
Execution Time: 458.026 ms
(20 rows)
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=26030.69..26030.70 rows=1 width=8) (actual time=385128.601..385128.661 rows=1 loops=1)
-> Nested Loop Anti Join (cost=1001.14..26030.67 rows=1 width=45) (actual time=544.672..385126.024 rows=499 loops=1)
-> Gather (cost=1000.57..18736.36 rows=1 width=60) (actual time=0.443..1.333 rows=499 loops=1)
Workers Planned: 2
Workers Launched: 2
-> Parallel Index Scan using xif11sep_info_report_extract on sep_info_report_extract sire (cost=0.57..17736.26 rows=1 width=60) (actual time=2.088..158.949 rows=166 loops=3)
Index Cond: ((reqt_processing_completed_dts >= $3) AND (reqt_processing_completed_dts <= (($4 + '1 day'::interval day) - '00:00:01'::interval second)))
Filter: (((reqt_failed_ind)::text <> '1'::text) AND ((reqxt_failed_ind IS NULL) OR ((reqxt_failed_ind)::text <> '1'::text)) AND ((resxt_failed_ind IS NULL) OR ((resxt_failed_ind)::text <> '1'::text)) AND ((reqtde_organization_type)::text <> 'SEW_EMPLOYER'::text) AND (req_valid_ind = '1'::numeric) AND (((res_valid_ind = '1'::numeric) AND ((rest_failed_ind)::text <> '1'::text)) OR ((res_valid_ind IS NULL) AND (rest_failed_ind IS NULL))) AND (reqte_endpoint_id = ($1)::numeric(38,0)) AND (reqtde_endpoint_id = ($2)::numeric(38,0)) AND ((rest_processing_completed_dts IS NOT NULL) OR (response_due_date < date_trunc('day'::text, timezone('America/New_York'::text, clock_timestamp())))))
Rows Removed by Filter: 162390
-> Index Scan using xif11sep_info_report_extract on sep_info_report_extract sire2 (cost=0.57..7294.30 rows=1 width=60) (actual time=771.787..771.787 rows=0 loops=499)
Index Cond: ((reqt_processing_completed_dts < sire.reqt_processing_completed_dts) AND (reqt_processing_completed_dts >= ($3 - '35 days'::interval day)) AND (reqt_processing_completed_dts <= (($4 + '1 day'::interval day) - '00:00:01'::interval second)))
Filter: ((rest_processing_completed_dts IS NOT NULL) AND ((reqt_failed_ind)::text <> '1'::text) AND ((reqxt_failed_ind IS NULL) OR ((reqxt_failed_ind)::text <> '1'::text)) AND ((rest_failed_ind)::text <> '1'::text) AND ((reqtde_organization_type)::text <> 'SEW_EMPLOYER'::text) AND (req_valid_ind = '1'::numeric) AND (res_valid_ind = '1'::numeric) AND (separation_request_id <> sire.separation_request_id) AND (reqte_endpoint_id = sire.reqte_endpoint_id) AND (reqtde_endpoint_id = sire.reqtde_endpoint_id) AND ((record_guid)::text = (sire.record_guid)::text) AND (reqte_endpoint_id = ($1)::numeric(38,0)) AND (reqtde_endpoint_id = ($2)::numeric(38,0)))
Rows Removed by Filter: 832551
Planning Time: 0.035 ms
Execution Time: 385128.742 ms
(15 rows)
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=176516.67..176516.68 rows=1 width=8)
-> Gather (cost=119912.80..176514.62 rows=117 width=45)
Workers Planned: 2
-> Parallel Hash Anti Join (cost=118912.80..175502.92 rows=49 width=45)
Hash Cond: ((sire.reqte_endpoint_id = sire2.reqte_endpoint_id) AND (sire.reqtde_endpoint_id = sire2.reqtde_endpoint_id) AND ((sire.record_guid)::text = (sire2.record_guid)::text))
Join Filter: ((sire2.separation_request_id <> sire.separation_request_id) AND (sire2.reqt_processing_completed_dts < sire.reqt_processing_completed_dts))
-> Parallel Index Scan using xif11sep_info_report_extract on sep_info_report_extract sire (cost=0.56..56589.56 rows=49 width=60)
Index Cond: ((reqt_processing_completed_dts >= '2022-08-01 00:00:00'::timestamp without time zone) AND (reqt_processing_completed_dts <= '2022-08-31 23:59:59'::timestamp without time zone))
Filter: (((reqt_failed_ind)::text <> '1'::text) AND ((reqxt_failed_ind IS NULL) OR ((reqxt_failed_ind)::text <> '1'::text)) AND ((resxt_failed_ind IS NULL) OR ((resxt_failed_ind)::text <> '1'::text)) AND ((reqtde_organization_type)::text <> 'SEW_EMPLOYER'::text) AND (req_valid_ind = '1'::numeric) AND (reqte_endpoint_id = '1'::numeric(38,0)) AND (reqtde_endpoint_id = '507650'::numeric(38,0)) AND (((res_valid_ind = '1'::numeric) AND ((rest_failed_ind)::text <> '1'::text)) OR ((res_valid_ind IS NULL) AND (rest_failed_ind IS NULL))) AND ((rest_processing_completed_dts IS NOT NULL) OR (response_due_date < date_trunc('day'::text, timezone('America/New_York'::text, clock_timestamp())))))
-> Parallel Hash (cost=118910.24..118910.24 rows=114 width=60)
-> Parallel Index Scan using xif11sep_info_report_extract on sep_info_report_extract sire2 (cost=0.56..118910.24 rows=114 width=60)
Index Cond: ((reqt_processing_completed_dts >= '2022-06-27 00:00:00'::timestamp without time zone) AND (reqt_processing_completed_dts <= '2022-08-31 23:59:59'::timestamp without time zone))
Filter: ((rest_processing_completed_dts IS NOT NULL) AND ((reqt_failed_ind)::text <> '1'::text) AND ((reqxt_failed_ind IS NULL) OR ((reqxt_failed_ind)::text <> '1'::text)) AND ((rest_failed_ind)::text <> '1'::text) AND ((reqtde_organization_type)::text <> 'SEW_EMPLOYER'::text) AND (req_valid_ind = '1'::numeric) AND (res_valid_ind = '1'::numeric) AND (reqte_endpoint_id = '1'::numeric(38,0)) AND (reqtde_endpoint_id = '507650'::numeric(38,0)))
(13 rows)
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=26166.99..26167.00 rows=1 width=8) (actual time=391386.247..391386.322 rows=1 loops=1)
-> Nested Loop Anti Join (cost=1001.14..26166.97 rows=1 width=45) (actual time=543.859..391383.467 rows=499 loops=1)
-> Gather (cost=1000.57..18838.10 rows=1 width=60) (actual time=0.433..1.328 rows=499 loops=1)
Workers Planned: 2
Workers Launched: 2
-> Parallel Index Scan using xif11sep_info_report_extract on sep_info_report_extract sire (cost=0.57..17838.00 rows=1 width=60) (actual time=1.975..157.645 rows=166 loops=3)
Index Cond: ((reqt_processing_completed_dts >= $3) AND (reqt_processing_completed_dts <= (($4 + '1 day'::interval day) - '00:00:01'::interval second)))
Filter: (((reqt_failed_ind)::text <> '1'::text) AND ((reqxt_failed_ind IS NULL) OR ((reqxt_failed_ind)::text <> '1'::text)) AND ((resxt_failed_ind IS NULL) OR ((resxt_failed_ind)::text <> '1'::text)) AND ((reqtde_organization_type)::text <> 'SEW_EMPLOYER'::text) AND (req_valid_ind = '1'::numeric) AND (((res_valid_ind = '1'::numeric) AND ((rest_failed_ind)::text <> '1'::text)) OR ((res_valid_ind IS NULL) AND (rest_failed_ind IS NULL))) AND (reqte_endpoint_id = ($1)::numeric(38,0)) AND (reqtde_endpoint_id = ($2)::numeric(38,0)) AND ((rest_processing_completed_dts IS NOT NULL) OR (response_due_date < date_trunc('day'::text, timezone('America/New_York'::text, clock_timestamp())))))
Rows Removed by Filter: 162390
-> Index Scan using xif11sep_info_report_extract on sep_info_report_extract sire2 (cost=0.57..7328.86 rows=1 width=60) (actual time=784.327..784.327 rows=0 loops=499)
Index Cond: ((reqt_processing_completed_dts < sire.reqt_processing_completed_dts) AND (reqt_processing_completed_dts >= ($3 - '35 days'::interval day)) AND (reqt_processing_completed_dts <= (($4 + '1 day'::interval day) - '00:00:01'::interval second)))
Filter: ((rest_processing_completed_dts IS NOT NULL) AND ((reqt_failed_ind)::text <> '1'::text) AND ((reqxt_failed_ind IS NULL) OR ((reqxt_failed_ind)::text <> '1'::text)) AND ((rest_failed_ind)::text <> '1'::text) AND ((reqtde_organization_type)::text <> 'SEW_EMPLOYER'::text) AND (req_valid_ind = '1'::numeric) AND (res_valid_ind = '1'::numeric) AND (separation_request_id <> sire.separation_request_id) AND (reqte_endpoint_id = sire.reqte_endpoint_id) AND (reqtde_endpoint_id = sire.reqtde_endpoint_id) AND ((record_guid)::text = (sire.record_guid)::text) AND (reqte_endpoint_id = ($1)::numeric(38,0)) AND (reqtde_endpoint_id = ($2)::numeric(38,0)))
Rows Removed by Filter: 832551
Planning Time: 0.837 ms
Execution Time: 391386.378 ms
(15 rows)
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=176516.79..176516.80 rows=1 width=8) (actual time=457.785..458.743 rows=1 loops=1)
-> Gather (cost=119912.87..176514.75 rows=117 width=45) (actual time=315.657..458.035 rows=499 loops=1)
Workers Planned: 2
Workers Launched: 2
-> Parallel Hash Anti Join (cost=118912.87..175503.05 rows=49 width=45) (actual time=310.574..454.297 rows=166 loops=3)
Hash Cond: ((sire.reqte_endpoint_id = sire2.reqte_endpoint_id) AND (sire.reqtde_endpoint_id = sire2.reqtde_endpoint_id) AND ((sire.record_guid)::text = (sire2.record_guid)::text))
Join Filter: ((sire2.separation_request_id <> sire.separation_request_id) AND (sire2.reqt_processing_completed_dts < sire.reqt_processing_completed_dts))
Rows Removed by Join Filter: 167
-> Parallel Index Scan using xif11sep_info_report_extract on sep_info_report_extract sire (cost=0.56..56589.62 rows=49 width=60) (actual time=1.286..144.841 rows=166 loops=3)
Index Cond: ((reqt_processing_completed_dts >= '2022-08-01 00:00:00'::timestamp without time zone) AND (reqt_processing_completed_dts <= '2022-08-31 23:59:59'::timestamp without time zone))
Filter: (((reqt_failed_ind)::text <> '1'::text) AND ((reqxt_failed_ind IS NULL) OR ((reqxt_failed_ind)::text <> '1'::text)) AND ((resxt_failed_ind IS NULL) OR ((resxt_failed_ind)::text <> '1'::text)) AND ((reqtde_organization_type)::text <> 'SEW_EMPLOYER'::text) AND (req_valid_ind = '1'::numeric) AND (reqte_endpoint_id = '1'::numeric(38,0)) AND (reqtde_endpoint_id = '507650'::numeric(38,0)) AND (((res_valid_ind = '1'::numeric) AND ((rest_failed_ind)::text <> '1'::text)) OR ((res_valid_ind IS NULL) AND (rest_failed_ind IS NULL))) AND ((rest_processing_completed_dts IS NOT NULL) OR (response_due_date < date_trunc('day'::text, timezone('America/New_York'::text, clock_timestamp())))))
Rows Removed by Filter: 162390
-> Parallel Hash (cost=118910.31..118910.31 rows=114 width=60) (actual time=309.163..309.164 rows=364 loops=3)
Buckets: 1024 Batches: 1 Memory Usage: 200kB
-> Parallel Index Scan using xif11sep_info_report_extract on sep_info_report_extract sire2 (cost=0.56..118910.31 rows=114 width=60) (actual time=1.943..308.876 rows=364 loops=3)
Index Cond: ((reqt_processing_completed_dts >= '2022-06-27 00:00:00'::timestamp without time zone) AND (reqt_processing_completed_dts <= '2022-08-31 23:59:59'::timestamp without time zone))
Filter: ((rest_processing_completed_dts IS NOT NULL) AND ((reqt_failed_ind)::text <> '1'::text) AND ((reqxt_failed_ind IS NULL) OR ((reqxt_failed_ind)::text <> '1'::text)) AND ((rest_failed_ind)::text <> '1'::text) AND ((reqtde_organization_type)::text <> 'SEW_EMPLOYER'::text) AND (req_valid_ind = '1'::numeric) AND (res_valid_ind = '1'::numeric) AND (reqte_endpoint_id = '1'::numeric(38,0)) AND (reqtde_endpoint_id = '507650'::numeric(38,0)))
Rows Removed by Filter: 358336
Planning Time: 0.842 ms
Execution Time: 458.793 ms
(20 rows)
