Jira (PDB-5451) Slow CTE query after upgrade Postgres to 11 PuppetDB 6.20

[Andrey Shukan (Jira)]

Andrey Shukan created an issue

PuppetDB / PDB-5451 Slow CTE query after upgrade Postgres to 11 PuppetDB 6.20 Issue Type: Bug Affects Versions: PDB 6.20.0 Assignee: Unassigned Components: PuppetDB Created: 2022/02/07 10:04 AM Priority: Medium Reporter: Andrey Shukan Hi, We have problems with CTE query performance after upgrade Postgres version from 9.6 to 11.14, earlier we tried upgrade Postgres up to version 14.1 but we returned to 9.6 and upgraded to 11.14.  Problems query looks like: WITH inactive_nodes AS (SELECT certname FROM certnames WHERE (deactivated IS NOT NULL AND deactivated > $10) OR (expired IS NOT NULL and expired > $11)), not_active_nodes AS (SELECT certname FROM certnames WHERE (deactivated IS NOT NULL OR expired IS NOT NULL)) SELECT fs.value AS "value" FROM (select certname, environment_id, $1::text as key, (stable||volatile)->$2 as value from factsets where (stable||volatile) ? $3) fs LEFT JOIN environments env ON fs.environment_id = env.id WHERE ((((fs.certname) in (SELECT certname FROM ( (SELECT c.certname AS "certname" FROM catalog_resources resources INNER JOIN certnames ON resources.certname_id = certnames.id INNER JOIN catalogs c ON c.certname = certnames.certname LEFT JOIN environments e ON c.environment_id = e.id LEFT JOIN resource_params_cache rpc ON rpc.resource = resources.resource WHERE ((type = $4) AND (title = $5))) ) sub)) AND ((fs.certname) in (SELECT certname FROM ( (SELECT fs.certname AS "certname" FROM (select certname, environment_id, (jsonb_each((stable||volatile))).* from factsets) fs LEFT JOIN environments env ON fs.environment_id = env.id WHERE ((fs.key = $6) AND (jsonb_typeof("value") = $7 AND (fs.value = $8)))) ) sub)) AND (fs.key = $9)) AND NOT ((fs.certname) in (SELECT certname FROM ( SELECT not_active_nodes.certname AS "certname" FROM not_active_nodes ) sub))) ORDER BY fs.certname Before upgrade this query executed on Postgres 9.6 master host this query executed duration: 4787.565 ms After upgrade Postgres version up to 11.14 or 14.1 more then 90 sec duration: 73802.410 ms In one of tickets we found workaround, as turned off parameter enable_nestloop = off; After that this query executed around duration: 3162.173 ms this action is affecting other queries in database but puppetdb application works without errors Query plan where enable_nestloop = off: -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- Merge Semi Join (cost=65428.52..65428.57 rows=1 width=59) (actual time=3631.574..3632.305 rows=2 loops=1) Merge Cond: (c.certname = fs.certname) Buffers: shared hit=115258 CTE not_active_nodes -> Seq Scan on certnames certnames_1 (cost=0.00..323.25 rows=197 width=26) (actual time=0.012..1.563 rows=197 loops=1) Filter: ((deactivated IS NOT NULL) OR (expired IS NOT NULL)) Rows Removed by Filter: 6478 Buffers: shared hit=123 -> Sort (cost=1620.16..1620.17 rows=1 width=119) (actual time=1385.789..1385.816 rows=17 loops=1) Sort Key: factsets.certname Sort Method: quicksort Memory: 30kB Buffers: shared hit=57302 -> Hash Semi Join (cost=1126.82..1620.15 rows=1 width=119) (actual time=15.123..1385.610 rows=38 loops=1) Hash Cond: (factsets.certname = c.certname) Buffers: shared hit=57302 -> Seq Scan on factsets (cost=12.31..505.64 rows=3 width=74) (actual time=2.513..1374.169 rows=6478 loops=1) Filter: ((NOT (hashed SubPlan 2)) AND ((stable || volatile) ? 'ipaddress'::text)) Rows Removed by Filter: 144 Buffers: shared hit=56848 SubPlan 2 -> CTE Scan on not_active_nodes (cost=0.00..11.82 rows=197 width=32) (actual time=0.016..1.700 rows=197 loops=1) Buffers: shared hit=123 -> Hash (cost=1110.57..1110.57 rows=121 width=53) (actual time=7.513..7.524 rows=38 loops=1) Buckets: 1024 Batches: 1 Memory Usage: 11kB Buffers: shared hit=454 -> Hash Join (cost=596.45..1110.57 rows=121 width=53) (actual time=2.672..7.484 rows=38 loops=1) Hash Cond: (c.certname = certnames.certname) Buffers: shared hit=454 -> Seq Scan on catalogs c (cost=0.00..485.66 rows=6622 width=35) (actual time=0.014..3.328 rows=6622 loops=1) Buffers: shared hit=287 -> Hash (cost=592.49..592.49 rows=122 width=26) (actual time=2.594..2.600 rows=38 loops=1) Buckets: 1024 Batches: 1 Memory Usage: 11kB Buffers: shared hit=167 -> Hash Join (cost=251.68..592.49 rows=122 width=26) (actual time=0.244..2.564 rows=38 loops=1) Hash Cond: (certnames.id = resources.certname_id) Buffers: shared hit=167 -> Seq Scan on certnames (cost=0.00..323.25 rows=6675 width=34) (actual time=0.005..1.034 rows=6675 loops=1) Buffers: shared hit=123 -> Hash (cost=247.72..247.72 rows=122 width=29) (actual time=0.194..0.197 rows=38 loops=1) Buckets: 1024 Batches: 1 Memory Usage: 11kB Buffers: shared hit=44 -> Index Scan using catalog_resources_type_title_idx on catalog_resources resources (cost=0.81..247.72 rows=122 width=29) (actual time=0.064..0.170 rows=38 loops=1) Index Cond: ((type = 'Class'::text) AND (title = 'Wg::Mgmt'::text)) Buffers: shared hit=44 -> Sort (cost=63485.11..63485.11 rows=1 width=35) (actual time=2245.248..2245.414 rows=3318 loops=1) Sort Key: fs.certname Sort Method: quicksort Memory: 356kB Buffers: shared hit=57938 -> Subquery Scan on fs (cost=0.00..63485.10 rows=1 width=35) (actual time=0.194..2227.419 rows=3318 loops=1) Filter: ((fs.key = 'site'::text) AND (fs.value = '"ed"'::jsonb) AND (jsonb_typeof(fs.value) = 'string'::text)) Rows Removed by Filter: 1233806 Buffers: shared hit=57938 -> Result (cost=0.00..36997.10 rows=662200 width=99) (actual time=0.180..2126.590 rows=1237124 loops=1) Buffers: shared hit=57938 -> ProjectSet (cost=0.00..10509.10 rows=662200 width=67) (actual time=0.173..1917.380 rows=1237124 loops=1) Buffers: shared hit=57938 -> Seq Scan on factsets factsets_1 (cost=0.00..443.66 rows=6622 width=74) (actual time=0.019..2.666 rows=6622 loops=1) Buffers: shared hit=245 Planning Time: 3.264 ms Execution Time: 3632.749 ms Query plan where enable_nestloop = on: --------------------------------------------------------------------------------------------------------------------------------------------------------------------------- Nested Loop Semi Join (cost=337.35..64779.33 rows=1 width=59) (actual time=30726.071..76727.877 rows=2 loops=1) Join Filter: (c.certname = fs.certname) Rows Removed by Join Filter: 124011 Buffers: shared hit=2305276 dirtied=5 CTE not_active_nodes -> Seq Scan on certnames certnames_1 (cost=0.00..323.25 rows=197 width=26) (actual time=0.010..0.979 rows=197 loops=1) Filter: ((deactivated IS NOT NULL) OR (expired IS NOT NULL)) Rows Removed by Filter: 6478 Buffers: shared hit=123 -> Nested Loop Semi Join (cost=14.10..970.95 rows=1 width=119) (actual time=8.852..1269.561 rows=38 loops=1) Buffers: shared hit=147776 dirtied=5 -> Index Scan using factsets_certname_idx on factsets (cost=12.60..941.74 rows=3 width=74) (actual time=1.395..1019.946 rows=6478 loops=1) Filter: ((NOT (hashed SubPlan 2)) AND ((stable || volatile) ? 'ipaddress'::text)) Rows Removed by Filter: 144 Buffers: shared hit=63202 dirtied=5 SubPlan 2 -> CTE Scan on not_active_nodes (cost=0.00..11.82 rows=197 width=32) (actual time=0.012..1.039 rows=197 loops=1) Buffers: shared hit=123 -> Nested Loop (cost=1.50..9.71 rows=1 width=53) (actual time=0.038..0.038 rows=0 loops=6478) Buffers: shared hit=84574 -> Nested Loop (cost=0.56..4.71 rows=1 width=61) (actual time=0.017..0.017 rows=1 loops=6478) Buffers: shared hit=39158 -> Index Scan using catalogs_certname_idx on catalogs c (cost=0.28..4.32 rows=1 width=35) (actual time=0.009..0.009 rows=1 loops=6478) Index Cond: (certname = factsets.certname) Buffers: shared hit=19724 -> Index Scan using certnames_transform_certname_key on certnames (cost=0.28..0.39 rows=1 width=34) (actual time=0.007..0.007 rows=1 loops=6478) Index Cond: (certname = c.certname) Buffers: shared hit=19434 -> Index Scan using catalog_resources_pkey1 on catalog_resources resources (cost=0.94..4.93 rows=1 width=29) (actual time=0.020..0.020 rows=0 loops=6478) Index Cond: ((certname_id = certnames.id) AND (type = 'Class'::text) AND (title = 'Wg::Mgmt'::text)) Buffers: shared hit=45416 -> Subquery Scan on fs (cost=0.00..63485.10 rows=1 width=35) (actual time=0.089..1984.836 rows=3264 loops=38) Filter: ((fs.key = 'site'::text) AND (fs.value = '"ed"'::jsonb) AND (jsonb_typeof(fs.value) = 'string'::text)) Rows Removed by Filter: 1211794 Buffers: shared hit=2157482 -> Result (cost=0.00..36997.10 rows=662200 width=99) (actual time=0.084..1896.011 rows=1215057 loops=38) Buffers: shared hit=2157482 -> ProjectSet (cost=0.00..10509.10 rows=662200 width=67) (actual time=0.082..1710.664 rows=1215057 loops=38) Buffers: shared hit=2157482 -> Seq Scan on factsets factsets_1 (cost=0.00..443.66 rows=6622 width=74) (actual time=0.004..2.442 rows=6504 loops=38) Buffers: shared hit=9115 Planning Time: 1.979 ms Execution Time: 76728.197 ms Before turning off enable_nestloop we tried run pg_repack, vacuum, analyze on all tables in puppetdb. How we can optimize this query ? Add Comment

This message was sent by Atlassian Jira (v8.20.2#820002-sha1:829506d)

[David McTavish (Jira)]

David McTavish updated an issue

PuppetDB / PDB-5451 Slow CTE query after upgrade Postgres to 11 PuppetDB 6.20

Change By: David McTavish Epic Link: PE-31891

Add Comment

[Austin Blatt (Jira)]

Austin Blatt commented on PDB-5451

Re: Slow CTE query after upgrade Postgres to 11 PuppetDB 6.20 Postgres seems to be underestimating the number of rows in your tables. You can find further information here https://www.cybertec-postgresql.com/en/join-strategies-and-performance-in-postgresql/. Under the heading "Impact on query performance" there's an explanation of how this underestimate leads Postgres to pick a plan using a nested loop join that ends up being slower. And following that section, under "How to make PostgreSQL choose the correct join strategy", there are a few additional things you can try. I would try out ANALYZE the table, perhaps with increased default_statistics_target and Configure the parameters that tell PostgreSQL about your hardware and resources: random_page_cost, effective_cache_size and effective_io_concurrency. ... The cost estimates of your two queries are very similar 64779.33 vs 65428.57, even though the performance is further apart, so even a small tweak to the hardware cost estimates could lead it to pick the more performant query.

Add Comment

[David McTavish (Jira)]

David McTavish updated an issue

PuppetDB / PDB-5451

Slow CTE query after upgrade Postgres to 11 PuppetDB 6.20

Change By: David McTavish Epic Link: PE-31891

Add Comment

[Sergey Siulin (Jira)]

Sergey Siulin commented on PDB-5451

Re: Slow CTE query after upgrade Postgres to 11 PuppetDB 6.20 Hello austin.blatt Postgresql chooses nested_join strategy because it doesn't predicate rows count on subquery (rows = 1 ?)

(cost=0.00..63485.10 rows=1 width=35) (actual time=0.089..1984.836 rows=3264 loops=38)

and nested_join should be better strategy here but actually we have 3264 rows and it cannot be predicted as we select values from jsonb (jsonb doesn't have inner statistics) statistics can be provided by indexes, but it cannot be used with function jsonb_each() By simple changing subquery (replace jsonb_each()) AND ((fs.certname) in ( SELECT certname from factsets LEFT JOIN environments env ON factsets.environment_id = env.id WHERE factsets.stable->'site' = '"XX"' OR factsets.volatile->'site' = '"XX"')) It decreased Execution Time to 1500 ms total So problem is in joining subquery results to main query with from_collapse_limit =4 merge behavior was changed and I got 5100ms total random_page_cost > 3 get me seqscan instead indexscan and replcaed nested_join to merge_join with 3100 ms total final plan is: Nested Loop Semi Join (cost=64692.22..64704.54 rows=1 width=59) (actual time=3163.202..3223.252 rows=2 loops=1) Output: ((factsets.stable || factsets.volatile) -> 'ipaddress'::text), factsets.certname CTE not_active_nodes -> Seq Scan on public.certnames certnames_1 (cost=0.00..323.37 rows=171 width=26) (actual time=0.050..1.634 rows=171 loops=1) Output: certnames_1.certname Filter: ((certnames_1.deactivated IS NOT NULL) OR (certnames_1.expired IS NOT NULL)) Rows Removed by Filter: 6515 -> Merge Semi Join (cost=64367.47..64367.52 rows=1 width=94) (actual time=3138.293..3142.540 rows=3250 loops=1) Output: factsets.stable, factsets.volatile, factsets.certname, fs.certname Merge Cond: (factsets.certname = fs.certname) -> Sort (cost=512.46..512.47 rows=3 width=75) (actual time=1171.151..1171.827 rows=4919 loops=1) Output: factsets.stable, factsets.volatile, factsets.certname, factsets.environment_id Output: factsets.stable, factsets.volatile, factsets.certname, factsets.environment_id Sort Key: factsets.certname Sort Method: quicksort Memory: 1142kB -> Seq Scan on public.factsets (cost=10.69..512.44 rows=3 width=75) (actual time=2.262..1136.062 rows=6515 loops=1) Output: factsets.stable, factsets.volatile, factsets.certname, factsets.environment_id Filter: ((NOT (hashed SubPlan 2)) AND ((factsets.stable || factsets.volatile) ? 'ipaddress'::text)) Rows Removed by Filter: 145 SubPlan 2 -> CTE Scan on not_active_nodes (cost=0.00..10.26 rows=171 width=32) (actual time=0.053..1.726 rows=171 loops=1) Output: not_active_nodes.certname -> Sort (cost=63855.01..63855.01 rows=1 width=35) (actual time=1966.436..1966.679 rows=3351 loops=1) Output: fs.environment_id, fs.certname Sort Key: fs.certname Sort Method: quicksort Memory: 358kB -> Subquery Scan on fs (cost=0.00..63855.00 rows=1 width=35) (actual time=0.324..1946.836 rows=3351 loops=1) Output: fs.environment_id, fs.certname Filter: ((fs.key = 'site'::text) AND (fs.value = '"XX"'::jsonb) AND (jsonb_typeof(fs.value) = 'string'::text)) Rows Removed by Filter: 1241383 -> Result (cost=0.00..37215.00 rows=666000 width=99) (actual time=0.314..1867.217 rows=1244734 loops=1) Output: factsets_1.certname, factsets_1.environment_id, ((jsonb_each((factsets_1.stable || factsets_1.volatile)))).key, ((jsonb_each((factsets_1.stable || factsets_1.volatile)))).value -> ProjectSet (cost=0.00..10575.00 rows=666000 width=67) (actual time=0.311..1703.734 rows=1244734 loops=1) Output: jsonb_each((factsets_1.stable || factsets_1.volatile)), factsets_1.certname, factsets_1.environment_id -> Seq Scan on public.factsets factsets_1 (cost=0.00..451.80 rows=6660 width=75) (actual time=0.009..2.291 rows=6660 loops=1) Output: factsets_1.id, factsets_1.certname, factsets_1."timestamp", factsets_1.environment_id, factsets_1.hash, factsets_1.producer_timestamp, factsets_1.producer_id, factsets_1.paths_hash, factsets_1.stable, factsets_1.stable_hash, factsets_1.volatile -> Nested Loop (cost=1.38..13.61 rows=1 width=53) (actual time=0.024..0.024 rows=0 loops=3250) Output: certnames.certname, c.certname Inner Unique: true -> Nested Loop (cost=0.56..6.73 rows=1 width=61) (actual time=0.014..0.015 rows=1 loops=3250) Output: certnames.id, certnames.certname, c.certname Inner Unique: true -> Index Scan using catalogs_certname_idx on public.catalogs c (cost=0.28..6.32 rows=1 width=35) (actual time=0.007..0.007 rows=1 loops=3250) Output: c.certname, c.environment_id Index Cond: (c.certname = factsets.certname) -> Index Scan using certnames_transform_certname_key on public.certnames (cost=0.28..0.41 rows=1 width=34) (actual time=0.007..0.007 rows=1 loops=3250) Output: certnames.id, certnames.certname, certnames.latest_report_id, certnames.deactivated, certnames.expired, certnames.package_hash, certnames.latest_report_timestamp, certnames.catalog_inputs_timestamp, certnames.catalog_inputs_uuid, certnames.catalog_inputs_hash Index Cond: (certnames.certname = c.certname) -> Index Scan using catalog_resources_pkey1 on public.catalog_resources resources (cost=0.81..6.78 rows=1 width=29) (actual time=0.010..0.010 rows=0 loops=3250) Output: resources.certname_id, resources.resource Index Cond: ((resources.certname_id = certnames.id) AND (resources.type = 'Class'::text) AND (resources.title = 'Wg::Mgmt'::text)) Planning Time: 3.584 ms Execution Time: 3223.577 ms P.S. I can't find any calls of CTE `inactive_nodes` in query, looks like ORM mistake

Add Comment