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.
