Inefficient Query Plans - Mailing list pgsql-performance
| From | Luke Chambers |
|---|---|
| Subject | Inefficient Query Plans |
| Date | |
| Msg-id | 1109110085.769681.93070@g14g2000cwa.googlegroups.com Whole thread Raw |
| Responses |
Re: Inefficient Query Plans
|
| List | pgsql-performance |
The following query plans both result from the very same query run on
different servers. They obviously differ drastically, but I don't why
as one db is a slonied copy of the other with identical postgresql.conf
files.
Both databases are vacuum analyzed nightly.
Here is the query:
------------------------------------------------------------------------
EXPLAIN ANALYZE
SELECT COUNT(DISTINCT(t.id)) FROM (
SELECT m_object_paper.id
FROM m_object_paper, m_assignment, m_class,
r_comment_rubric_user_object
WHERE m_object_paper.assignment=m_assignment.id
AND m_assignment.class=m_class.id
AND m_class.account IN (SELECT * FROM children_of(32660) as acts)
AND m_object_paper.id = r_comment_rubric_user_object.objectid
UNION
SELECT m_object_paper.id
FROM m_object_paper, m_assignment, m_class, r_quickmark_user_object
WHERE m_object_paper.assignment=m_assignment.id
AND m_assignment.class=m_class.id
AND m_class.account IN (SELECT * FROM children_of(32660) acts)
AND m_object_paper.id = r_quickmark_user_object.objectid)as t;
------------------------------------------------------------------------
-------------------
DB1 QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=314616.49..314616.49 rows=1 width=4) (actual
time=853.483..853.484 rows=1 loops=1)
-> Subquery Scan t (cost=314568.97..314609.70 rows=2715 width=4)
(actual time=848.574..852.912 rows=354 loops=1)
-> Unique (cost=314568.97..314582.55 rows=2715 width=4)
(actual time=848.568..852.352 rows=354 loops=1)
-> Sort (cost=314568.97..314575.76 rows=2715 width=4)
(actual time=848.565..850.264 rows=2428 loops=1)
Sort Key: id
-> Append (cost=153181.39..314414.12 rows=2715
width=4) (actual time=224.984..844.714 rows=2428 loops=1)
-> Subquery Scan "*SELECT* 1"
(cost=153181.39..159900.66 rows=2250 width=4) (actual
time=224.981..700.687 rows=2116 loops=1)
-> Hash Join
(cost=153181.39..159878.16 rows=2250 width=4) (actual
time=224.975..696.639 rows=2116 loops=1)
Hash Cond: ("outer".objectid =
"inner".id)
-> Seq Scan on
r_comment_rubric_user_object (cost=0.00..5144.18 rows=306018 width=4)
(actual time=0.021..405.881 rows=306392 loops=1)
-> Hash
(cost=153072.40..153072.40 rows=43595 width=4) (actual
time=32.311..32.311 rows=0 loops=1)
-> Nested Loop
(cost=15.00..153072.40 rows=43595 width=4) (actual time=0.554..29.762
rows=2033 loops=1)
-> Nested Loop
(cost=15.00..16071.65 rows=3412 width=4) (actual time=0.512..3.657
rows=180 loops=1)
-> Nested
Loop (cost=15.00..3769.73 rows=1666 width=4) (actual time=0.452..0.943
rows=50 loops=1)
->
HashAggregate (cost=15.00..15.00 rows=200 width=4) (actual
time=0.388..0.394 rows=1 loops=1)
->
Function Scan on children_of acts (cost=0.00..12.50 rows=1000
width=4) (actual time=0.376..0.377 rows=1 loops=1)
->
Index Scan using m_class_account_idx on m_class (cost=0.00..18.67
rows=8 width=8) (actual time=0.057..0.416 rows=50 loops=1)
Index Cond: (m_class.account = "outer".acts)
-> Index Scan
using m_assignment_class_idx on m_assignment (cost=0.00..7.25 rows=11
width=8) (actual time=0.023..0.043 rows=4 loops=50)
Index
Cond: (m_assignment."class" = "outer".id)
-> Index Scan using
m_object_paper_assignment_idx on m_object_paper (cost=0.00..39.24
rows=73 width=8) (actual time=0.026..0.118 rows=11 loops=180)
Index Cond:
(m_object_paper."assignment" = "outer".id)
-> Subquery Scan "*SELECT* 2"
(cost=153181.39..154513.46 rows=465 width=4) (actual
time=54.883..140.747 rows=312 loops=1)
-> Hash Join
(cost=153181.39..154508.81 rows=465 width=4) (actual
time=54.875..140.161 rows=312 loops=1)
Hash Cond: ("outer".objectid =
"inner".id)
-> Seq Scan on
r_quickmark_user_object (cost=0.00..1006.85 rows=63185 width=4)
(actual time=0.007..70.446 rows=63268 loops=1)
-> Hash
(cost=153072.40..153072.40 rows=43595 width=4) (actual
time=17.633..17.633 rows=0 loops=1)
-> Nested Loop
(cost=15.00..153072.40 rows=43595 width=4) (actual time=0.549..15.186
rows=2033 loops=1)
-> Nested Loop
(cost=15.00..16071.65 rows=3412 width=4) (actual time=0.515..2.406
rows=180 loops=1)
-> Nested
Loop (cost=15.00..3769.73 rows=1666 width=4) (actual time=0.482..0.792
rows=50 loops=1)
->
HashAggregate (cost=15.00..15.00 rows=200 width=4) (actual
time=0.443..0.449 rows=1 loops=1)
->
Function Scan on children_of acts (cost=0.00..12.50 rows=1000
width=4) (actual time=0.428..0.429 rows=1 loops=1)
->
Index Scan using m_class_account_idx on m_class (cost=0.00..18.67
rows=8 width=8) (actual time=0.029..0.219 rows=50 loops=1)
Index Cond: (m_class.account = "outer".acts)
-> Index Scan
using m_assignment_class_idx on m_assignment (cost=0.00..7.25 rows=11
width=8) (actual time=0.013..0.023 rows=4 loops=50)
Index
Cond: (m_assignment."class" = "outer".id)
-> Index Scan using
m_object_paper_assignment_idx on m_object_paper (cost=0.00..39.24
rows=73 width=8) (actual time=0.011..0.048 rows=11 loops=180)
Index Cond:
(m_object_paper."assignment" = "outer".id)
Total runtime: 854.101 ms
-------------------
DB2 QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=431500.82..431500.82 rows=1 width=4) (actual
time=161604.563..161604.568 rows=1 loops=1)
-> Subquery Scan t (cost=431025.16..431432.86 rows=27180 width=4)
(actual time=161571.533..161602.095 rows=354 loops=1)
-> Unique (cost=431025.16..431161.06 rows=27180 width=4)
(actual time=161571.515..161598.311 rows=354 loops=1)
-> Sort (cost=431025.16..431093.11 rows=27180 width=4)
(actual time=161571.502..161583.783 rows=2428 loops=1)
Sort Key: id
-> Append (cost=203789.85..429023.32 rows=27180
width=4) (actual time=79513.023..161555.122 rows=2428 loops=1)
-> Subquery Scan "*SELECT* 1"
(cost=203789.85..216527.64 rows=22528 width=4) (actual
time=79513.012..82516.102 rows=2116 loops=1)
-> Hash Join
(cost=203789.85..216302.36 rows=22528 width=4) (actual
time=79512.998..82493.092 rows=2116 loops=1)
Hash Cond: ("outer".objectid =
"inner".id)
-> Seq Scan on
r_comment_rubric_user_object (cost=0.00..5133.34 rows=306034 width=4)
(actual time=0.045..1769.838 rows=306390 loops=1)
-> Hash
(cost=201205.35..201205.35 rows=436601 width=4) (actual
time=78627.830..78627.830 rows=0 loops=1)
-> Hash Join
(cost=25006.81..201205.35 rows=436601 width=4) (actual
time=9572.704..78612.859 rows=2033 loops=1)
Hash Cond:
("outer"."assignment" = "inner".id)
-> Seq Scan on
m_object_paper (cost=0.00..142176.19 rows=5931219 width=8) (actual
time=0.085..36433.616 rows=5934777 loops=1)
-> Hash
(cost=24921.40..24921.40 rows=34160 width=4) (actual
time=8636.897..8636.897 rows=0 loops=1)
-> Hash Join
(cost=8773.25..24921.40 rows=34160 width=4) (actual
time=3013.277..8635.612 rows=180 loops=1)
Hash
Cond: ("outer"."class" = "inner".id)
-> Seq
Scan on m_assignment (cost=0.00..13486.37 rows=464037 width=8) (actual
time=0.037..2903.799 rows=464639 loops=1)
-> Hash
(cost=8731.55..8731.55 rows=16682 width=4) (actual
time=2985.051..2985.051 rows=0 loops=1)
->
Hash Join (cost=15.50..8731.55 rows=16682 width=4) (actual
time=716.452..2984.651 rows=50 loops=1)
Hash Cond: ("outer".account = "inner".acts)
-> Seq Scan on m_class (cost=0.00..7416.15 rows=226615 width=8)
(actual time=0.042..1586.784 rows=226796 loops=1)
-> Hash (cost=15.00..15.00 rows=200 width=4) (actual
time=0.548..0.548 rows=0 loops=1)
-> HashAggregate (cost=15.00..15.00 rows=200 width=4)
(actual time=0.519..0.527 rows=1 loops=1)
-> Function Scan on children_of acts (cost=0.00..12.50
rows=1000 width=4) (actual time=0.485..0.491 rows=1 loops=1)
-> Subquery Scan "*SELECT* 2"
(cost=203789.85..212495.68 rows=4652 width=4) (actual
time=78431.905..79014.599 rows=312 loops=1)
-> Hash Join
(cost=203789.85..212449.16 rows=4652 width=4) (actual
time=78431.889..79011.085 rows=312 loops=1)
Hash Cond: ("outer".objectid =
"inner".id)
-> Seq Scan on
r_quickmark_user_object (cost=0.00..1006.95 rows=63195 width=4)
(actual time=0.085..391.887 rows=63268 loops=1)
-> Hash
(cost=201205.35..201205.35 rows=436601 width=4) (actual
time=78182.649..78182.649 rows=0 loops=1)
-> Hash Join
(cost=25006.81..201205.35 rows=436601 width=4) (actual
time=9328.018..78167.922 rows=2033 loops=1)
Hash Cond:
("outer"."assignment" = "inner".id)
-> Seq Scan on
m_object_paper (cost=0.00..142176.19 rows=5931219 width=8) (actual
time=0.052..36243.971 rows=5934777 loops=1)
-> Hash
(cost=24921.40..24921.40 rows=34160 width=4) (actual
time=8416.317..8416.317 rows=0 loops=1)
-> Hash Join
(cost=8773.25..24921.40 rows=34160 width=4) (actual
time=2801.934..8415.065 rows=180 loops=1)
Hash
Cond: ("outer"."class" = "inner".id)
-> Seq
Scan on m_assignment (cost=0.00..13486.37 rows=464037 width=8) (actual
time=0.121..2899.409 rows=464639 loops=1)
-> Hash
(cost=8731.55..8731.55 rows=16682 width=4) (actual
time=2772.260..2772.260 rows=0 loops=1)
->
Hash Join (cost=15.50..8731.55 rows=16682 width=4) (actual
time=674.259..2771.886 rows=50 loops=1)
Hash Cond: ("outer".account = "inner".acts)
-> Seq Scan on m_class (cost=0.00..7416.15 rows=226615 width=8)
(actual time=0.049..1430.376 rows=226796 loops=1)
-> Hash (cost=15.00..15.00 rows=200 width=4) (actual
time=0.647..0.647 rows=0 loops=1)
-> HashAggregate (cost=15.00..15.00 rows=200 width=4)
(actual time=0.604..0.613 rows=1 loops=1)
-> Function Scan on children_of acts (cost=0.00..12.50
rows=1000 width=4) (actual time=0.568..0.574 rows=1 loops=1)
Total runtime: 161605.867
--------------------------
--------------------------
Additionally, we have a db3 which was originally in agreement w/ db1
and
executing the more efficient plan. However, now it is in agreement with
db2
with the less efficient, slower plan.
What could be causing this?
Thanks for your help.
pgsql-performance by date: