Analyzing performance regression from 9.2 to 9.6

From: Dave Peticolas <dave(at)krondo(dot)com>
To: pgsql-general <pgsql-general(at)postgresql(dot)org>
Subject: Analyzing performance regression from 9.2 to 9.6
Date: 2017-09-09 22:26:10
Message-ID: CAPRbp06+fgvpr70mq6rnkPhhW6i+y2168dwHkGy0rc3k7cZk2w@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-general

Hi, I am trying to analyze a performance regression from 9.2.21 to 9.6.3.
The query and execution plans are below with 9.6.3 first. If the query
looks a bit odd, it was generated by an ORM and the names have been
modified. The slight difference in row counts is because they are from
snapshots taken at slightly different times, but the performance difference
has been very robust against different snapshot versions and also
reanalyzing the tables with different default_statistics_target settings
(up to 10000).

If I am reading the plans correctly, the difference seems to be in some
extra Join Filter operations that 9.6.3 performs.

I realize the query itself is probably not great and would benefit from a
different approach, but I'd like to know if there are 9.6 settings I should
look into to get a better plan without changing the query if possible.

thank you

SELECT COUNT(*)
FROM
(SELECT "report_skilltype"."uuid" AS Col1
FROM "report_skilltype"
INNER JOIN "kbdata_skill"
ON ("report_skilltype"."skill_id" = "kbdata_skill"."id")
INNER JOIN "product_kbdata_skills"
ON ("kbdata_skill"."id" = "product_kbdata_skills"."skill_id")
LEFT OUTER JOIN "report_submission"
ON ("report_skilltype"."uuid" = "report_submission"."skill_type_id")
INNER JOIN "report_type"
ON ("report_skilltype"."type_id" = "report_type"."id")
INNER JOIN "kbdata_skill_aspects"
ON ("kbdata_skill"."id" = "kbdata_skill_aspects"."skill_id")
LEFT OUTER JOIN "report_typereport"
ON ("report_skilltype"."uuid" = "report_typereport"."skill_type_id")
WHERE ("product_kbdata_skills"."product_id" IS NOT NULL
AND "report_submission"."id" IS NULL
AND "report_type"."is_current" = false
AND "kbdata_skill_aspects"."aspect_id" IS NOT NULL
AND NOT (("kbdata_skill"."external_uuid" = %s
OR "report_skilltype"."skill_id" IN (
SELECT U2."skill_id" AS Col1
FROM "product_kbdata_skills" U2
INNER JOIN "product" U3
ON (U2."product_id" = U3."id")
WHERE U3."slug" = %s)
OR "report_type"."category"
IN (%s, %s))))
ORDER BY "report_typereport"."id" DESC
LIMIT 86) subquery;

Aggregate (cost=82730.06..82730.07 rows=1 width=8) (actual
time=395510.081..395510.081 rows=1 loops=1)
-> Limit (cost=82730.05..82730.05 rows=1 width=20) (actual
time=395510.077..395510.077 rows=0 loops=1)
-> Sort (cost=82730.05..82730.05 rows=1 width=20) (actual
time=395510.077..395510.077 rows=0 loops=1)
Sort Key: report_typereport.id DESC
Sort Method: quicksort Memory: 25kB
-> Nested Loop Left Join (cost=55430.43..82730.04 rows=1
width=20) (actual time=395510.048..395510.048 rows=0 loops=1)
-> Nested Loop (cost=55430.01..82729.43 rows=1
width=16) (actual time=395510.048..395510.048 rows=0 loops=1)
-> Nested Loop (cost=55429.58..82728.74 rows=1
width=20) (actual time=2320.731..383899.750 rows=463108 loops=1)
Join Filter: (report_skilltype.skill_id =
product_kbdata_skills.skill_id)
Rows Removed by Join Filter: 244680956
-> Nested Loop (cost=55429.58..82713.86
rows=1 width=32) (actual time=2320.719..292590.749 rows=464288 loops=1)
Join Filter:
(report_skilltype.skill_id = kbdata_skill.id)
Rows Removed by Join Filter:
251179808
-> Nested Loop
(cost=55429.58..82687.30 rows=1 width=28) (actual
time=2318.808..163425.963 rows=464288 loops=1)
Join Filter:
(report_skilltype.skill_id = kbdata_skill_aspects.skill_id)
Rows Removed by Join Filter:
444896473
-> Index Only Scan using
kbdata_skill_aspects_skill_id_5407f958fea94362_uniq on kbdata_skill_aspects
(cost=0.27..23.05 rows=387 width=4) (actual time=1.317..1.924 rows=387
loops=1)
Index Cond: (aspect_id
IS NOT NULL)
Heap Fetches: 0
-> Materialize
(cost=55429.31..82658.45 rows=1 width=24) (actual time=5.983..218.987
rows=1150803 loops=387)
-> Hash Right Join
(cost=55429.31..82658.45 rows=1 width=24) (actual time=2314.690..2956.164
rows=1150803 loops=1)
Hash Cond:
(report_submission.skill_type_id = report_skilltype.uuid)
Filter: (
report_submission.id IS NULL)
Rows Removed by
Filter: 489981
-> Seq Scan on
report_submission (cost=0.00..10488.81 rows=489981 width=39) (actual
time=2.886..512.928 rows=489981 loops=1)
-> Hash
(cost=40399.71..40399.71 rows=818608 width=24) (actual
time=1615.128..1615.128 rows=1637183 loops=1)
Buckets:
524288 (originally 524288) Batches: 4 (originally 2) Memory Usage: 28673kB
-> Seq Scan
on report_skilltype (cost=13.51..40399.71 rows=818608 width=24) (actual
time=3.413..1050.734 rows=1637183 loops=1)

Filter: (NOT (hashed SubPlan 1))
Rows
Removed by Filter: 33

SubPlan 1
->
Hash Join (cost=1.05..13.07 rows=176 width=4) (actual time=0.076..0.224
rows=26 loops=1)

Hash Cond: (u2.product_id = u3.id)

-> Seq Scan on product_kbdata_skills u2 (cost=0.00..8.28 rows=528
width=8) (actual time=0.004..0.092 rows=528 loops=1)

-> Hash (cost=1.04..1.04 rows=1 width=4) (actual time=0.014..0.014
rows=1 loops=1)

Buckets: 1024 Batches: 1 Memory Usage: 9kB

-> Seq Scan on product u3 (cost=0.00..1.04 rows=1 width=4) (actual
time=0.010..0.011 rows=1 loops=1)

Filter: ((slug)::text = 'product1'::text)

Rows Removed by Filter: 2
-> Seq Scan on kbdata_skill
(cost=0.00..19.79 rows=542 width=4) (actual time=0.002..0.187 rows=542
loops=464288)
Filter: (external_uuid <>
'CE9EC8A7-80D8-42A2-B506-0C1B7248CF8C'::uuid)
Rows Removed by Filter: 1
-> Seq Scan on product_kbdata_skills
(cost=0.00..8.28 rows=528 width=4) (actual time=0.001..0.100 rows=528
loops=464288)
Filter: (product_id IS NOT NULL)
-> Index Scan using report_type_pkey on
report_type (cost=0.43..0.68 rows=1 width=4) (actual time=0.025..0.025
rows=0 loops=463108)
Index Cond: (id = report_skilltype.type_id)
Filter: ((NOT is_current) AND (category <>
ALL ('{7,8}'::integer[])))
Rows Removed by Filter: 1
-> Index Scan using report_typereport_4bacbe76 on
report_typereport (cost=0.42..0.60 rows=1 width=20) (never executed)
Index Cond: (report_skilltype.uuid =
skill_type_id)
Planning time: 342.295 ms
Execution time: 395519.803 ms
(52 rows)

Aggregate (cost=84616.61..84616.62 rows=1 width=0) (actual
time=181341.236..181341.236 rows=1 loops=1)
-> Limit (cost=84616.59..84616.60 rows=1 width=20) (actual
time=181341.233..181341.233 rows=0 loops=1)
-> Sort (cost=84616.59..84616.60 rows=1 width=20) (actual
time=181341.232..181341.232 rows=0 loops=1)
Sort Key: report_typereport.id
Sort Method: quicksort Memory: 25kB
-> Nested Loop Left Join (cost=55041.27..84616.58 rows=1
width=20) (actual time=181341.227..181341.227 rows=0 loops=1)
-> Nested Loop (cost=55041.27..84615.95 rows=1
width=16) (actual time=181341.226..181341.226 rows=0 loops=1)
-> Nested Loop (cost=55041.27..84614.95 rows=1
width=20) (actual time=1439.099..179492.134 rows=455131 loops=1)
-> Nested Loop (cost=55041.27..84614.67
rows=1 width=32) (actual time=1439.092..178512.732 rows=456311 loops=1)
-> Nested Loop
(cost=55041.27..84614.38 rows=1 width=28) (actual
time=1439.073..177379.411 rows=456311 loops=1)
Join Filter:
(report_skilltype.skill_id = kbdata_skill_aspects.skill_id)
Rows Removed by Join Filter:
441816577
-> Index Only Scan using
kbdata_skill_aspects_skill_id_5407f958fea94362_uniq on kbdata_skill_aspects
(cost=0.00..23.02 rows=387 width=4) (actual time=0.011..0.651 rows=387
loops=1)
Index Cond: (aspect_id
IS NOT NULL)
Heap Fetches: 0
-> Materialize
(cost=55041.27..84585.56 rows=1 width=24) (actual time=3.711..224.082
rows=1142824 loops=387)
-> Hash Right Join
(cost=55041.27..84585.55 rows=1 width=24) (actual time=1435.029..2180.291
rows=1142824 loops=1)
Hash Cond:
(report_submission.skill_type_id = report_skilltype.uuid)
Filter: (
report_submission.id IS NULL)
Rows Removed by
Filter: 479828
-> Seq Scan on
report_submission (cost=0.00..10236.91 rows=475491 width=40) (actual
time=0.003..119.861 rows=479828 loops=1)
-> Hash
(cost=40175.69..40175.69 rows=809647 width=24) (actual
time=1105.173..1105.173 rows=1619274 loops=1)
Buckets:
65536 Batches: 4 (originally 2) Memory Usage: 32769kB
-> Seq Scan
on report_skilltype (cost=13.51..40175.69 rows=809647 width=24) (actual
time=0.226..544.799 rows=1619274 loops=1)

Filter: (NOT (hashed SubPlan 1))
Rows
Removed by Filter: 33

SubPlan 1
->
Hash Join (cost=1.05..13.07 rows=176 width=4) (actual time=0.060..0.205
rows=26 loops=1)

Hash Cond: (u2.product_id = u3.id)

-> Seq Scan on product_kbdata_skills u2 (cost=0.00..8.28 rows=528
width=8) (actual time=0.002..0.083 rows=528 loops=1)

-> Hash (cost=1.04..1.04 rows=1 width=4) (actual time=0.009..0.009
rows=1 loops=1)

Buckets: 1024 Batches: 1 Memory Usage: 1kB

-> Seq Scan on product u3 (cost=0.00..1.04 rows=1 width=4) (actual
time=0.006..0.007 rows=1 loops=1)

Filter: ((slug)::text = 'product1'::text)

Rows Removed by Filter: 2
-> Index Scan using
kbdata_skill_pkey on kbdata_skill (cost=0.00..0.27 rows=1 width=4) (actual
time=0.001..0.002 rows=1 loops=456311)
Index Cond: (id =
report_skilltype.skill_id)
Filter: (external_uuid <>
'CE9EC8A7-80D8-42A2-B506-0C1B7248CF8C'::uuid)
-> Index Scan using
product_kbdata_skills_daa24ab7 on product_kbdata_skills (cost=0.00..0.27
rows=1 width=4) (actual time=0.001..0.001 rows=1 loops=456311)
Index Cond: (skill_id =
report_skilltype.skill_id)
Filter: (product_id IS NOT NULL)
-> Index Scan using report_type_pkey on
report_type (cost=0.00..0.99 rows=1 width=4) (actual time=0.004..0.004
rows=0 loops=455131)
Index Cond: (id = report_skilltype.type_id)
Filter: ((NOT is_current) AND (category <>
ALL ('{7,8}'::integer[])))
Rows Removed by Filter: 1
-> Index Scan using report_typereport_4bacbe76 on
report_typereport (cost=0.00..0.62 rows=1 width=20) (never executed)
Index Cond: (report_skilltype.uuid =
skill_type_id)
Total runtime: 181349.830 ms
(48 rows)

Responses

Browse pgsql-general by date

  From Date Subject
Next Message techmail+pgsql 2017-09-10 01:44:08 pg_ident mapping Kerberos Usernames
Previous Message Nico Williams 2017-09-08 23:26:43 Re: Aquameta 0.1 - Request for reviews, contributors