Re: full vacuum really slows down query

I am resending this is plain text as it was rejected. What is the best
way to include this kind of output to the mailing list?

I would greatly appreciate any advice on how to read the following
output from EXPLAIN ANALYZE.

When running the query the first time from a fresh restore it takes
about 55 sec.
On a second run is take about 2 sec.
After the vacuum it takes about 36 sec no matter how many times I run it.

My application is growing rapidly in both size and complexity. I really
need to get a handle on this soon.

*Query run from a fresh restore*
"Sort (cost=242145.26..242145.27 rows=1 width=1200) (actual
time=55100.785..55100.820 rows=158 loops=1)"
" Sort Key: (sum(pipe0_1_.numpieces)), (sum(pipe0_.numfeet))"
" Sort Method: quicksort Memory: 52kB"
" -> HashAggregate (cost=242145.24..242145.25 rows=1 width=1200)
(actual time=55099.970..55100.194 rows=158 loops=1)"
" -> Nested Loop (cost=0.00..242145.20 rows=1 width=1200)
(actual time=391.496..55092.841 rows=427 loops=1)"
" Join Filter: (pipe0_.popipe_id = popipe1_.id)"
" -> Nested Loop (cost=0.00..240701.08 rows=1 width=684)
(actual time=2.543..-2171.666 rows=3174 loops=1)"
" -> Nested Loop (cost=0.00..240700.46 rows=1
width=676) (actual time=2.486..-1946.110 rows=3174 loops=1)"
" -> Nested Loop (cost=0.00..240699.93 rows=1
width=644) (actual time=2.431..-1462.137 rows=3174 loops=1)"
" -> Nested Loop (cost=0.00..240699.56
rows=1 width=136) (actual time=2.357..-2010.958 rows=3174 loops=1)"
" -> Nested Loop
(cost=0.00..240698.36 rows=1 width=128) (actual time=2.279..-1534.495
rows=3174 loops=1)"
" -> Nested Loop
(cost=0.00..240698.08 rows=1 width=136) (actual time=0.909..-1323.123
rows=6066 loops=1)"
" -> Nested Loop
(cost=0.00..240692.30 rows=1 width=136) (actual time=0.882..-1625.883
rows=6066 loops=1)"
" -> Nested
Loop (cost=0.00..240690.71 rows=3 width=104) (actual
time=0.826..-1155.887 rows=6066 loops=1)"
" ->
Nested Loop (cost=0.00..240665.27 rows=48 width=72) (actual
time=0.766..-436.684 rows=7236 loops=1)"
" ->
Index Scan using t_pipe_pkey on t_pipe pipe0_ (cost=0.00..240391.77
rows=48 width=56) (actual time=0.759..796.516 rows=7236 loops=1)"
"
Filter: ((subplan) IS NULL)"
"
SubPlan"
"
-> Nested Loop Left Join (cost=0.00..24.85 rows=1 width=8) (actual
time=0.048..0.077 rows=1 loops=9644)"
"
-> Nested Loop (cost=0.00..16.55 rows=1 width=48) (actual
time=-0.013..0.042 rows=1 loops=9644)"
"
-> Index Scan using t_pipe_pkey on t_pipe p (cost=0.00..8.27 rows=1
width=48) (actual time=-0.021..0.006 rows=1 loops=9644)"
"
Index Cond: (id = $0)"
"
-> Index Scan using t_generic_item_pkey on t_generic_item gi
(cost=0.00..8.27 rows=1 width=16) (actual time=0.057..0.031 rows=1
loops=9644)"
"
Index Cond: (gi.id = $0)"
"
-> Index Scan using uk_projection_weight_grade_endfinish_actor_condtion
on t_projection pr (cost=0.00..8.28 rows=1 width=56) (actual
time=0.005..0.005 rows=0 loops=9644)"
"
Index Cond: ((pr.popipe_id = p.popipe_id) AND (pr.weight_id =
p.weight_id) AND (pr.grade_id = p.grade_id) AND (pr.endfinish_id =
p.endfinish_id) AND (pr.actor_id = gi.actor_id) AND (pr.condition_id =
p.condition_id))"
" ->
Index Scan using t_generic_item_pkey on t_generic_item pipe0_1_
(cost=0.00..5.69 rows=1 width=32) (actual time=-0.068..-0.138 rows=1
loops=7236)"
"
Index Cond: (pipe0_1_.id = pipe0_.id)"
" -> Index
Scan using pk_t_condition on t_condition condition7_ (cost=0.00..0.52
rows=1 width=40) (actual time=0.039..0.004 rows=1 loops=7236)"
"
Index Cond: (condition7_.id = pipe0_.condition_id)"
"
Filter: condition7_.needsprojection"
" -> Index Scan
using pk_t_endfinish on t_endfinish endfinish4_ (cost=0.00..0.52 rows=1
width=40) (actual time=0.045..0.004 rows=1 loops=6066)"
" Index
Cond: (endfinish4_.id = pipe0_.endfinish_id)"
" -> Index Scan using
t_action_pkey on t_state state9_ (cost=0.00..5.77 rows=1 width=16)
(actual time=0.004..0.089 rows=1 loops=6066)"
" Index Cond:
(state9_.id = pipe0_1_.state_id)"
" -> Index Scan using
pk_t_status on t_status status10_ (cost=0.00..0.27 rows=1 width=8)
(actual time=-0.080..-0.037 rows=1 loops=6066)"
" Index Cond:
(status10_.id = state9_.status_id)"
" Filter:
status10_.needsprojection"
" -> Index Scan using pk_t_actor
on t_actor actor5_ (cost=0.00..1.18 rows=1 width=16) (actual
time=0.006..-0.154 rows=1 loops=3174)"
" Index Cond: (actor5_.id =
pipe0_1_.actor_id)"
" -> Index Scan using pk_t_contact on
t_contact contact6_ (cost=0.00..0.36 rows=1 width=524) (actual
time=0.086..0.169 rows=1 loops=3174)"
" Index Cond: (contact6_.id =
actor5_.contact_id)"
" -> Index Scan using pk_t_grade on t_grade
grade3_ (cost=0.00..0.52 rows=1 width=40) (actual time=0.004..-0.156
rows=1 loops=3174)"
" Index Cond: (grade3_.id = pipe0_.grade_id)"
" -> Index Scan using pk_t_weight on t_weight
weight2_ (cost=0.00..0.60 rows=1 width=16) (actual time=0.004..0.006
rows=1 loops=3174)"
" Index Cond: (weight2_.id = pipe0_.weight_id)"
" -> Merge Join (cost=0.00..1428.20 rows=1274 width=532)
(actual time=0.531..17.466 rows=998 loops=3174)"
" Merge Cond: (popipe1_.id = popipe1_1_.id)"
" -> Index Scan using t_po_pipe_pkey on t_po_pipe
popipe1_ (cost=0.00..170.49 rows=2549 width=8) (actual
time=0.335..2.914 rows=2549 loops=3174)"
" -> Index Scan using t_action_pkey on t_state
popipe1_1_ (cost=0.00..1229.50 rows=3641 width=524) (actual
time=0.092..10.843 rows=5727 loops=3174)"
" Filter: (NOT popipe1_1_.spec)"
"Total runtime: 55101.547 ms"

*Before vacuum but after a second run of the query*

"Sort (cost=241636.97..241637.00 rows=10 width=183) (actual
time=2182.240..2182.273 rows=158 loops=1)"
" Sort Key: (sum(pipe0_1_.numpieces)), (sum(pipe0_.numfeet))"
" Sort Method: quicksort Memory: 52kB"
" -> HashAggregate (cost=241636.63..241636.81 rows=10 width=183)
(actual time=1924.839..1925.114 rows=158 loops=1)"
" -> Nested Loop (cost=467.32..241636.26 rows=10 width=183)
(actual time=29.712..1922.303 rows=427 loops=1)"
" -> Hash Join (cost=467.32..241630.12 rows=10 width=175)
(actual time=29.701..1662.213 rows=427 loops=1)"
" Hash Cond: (pipe0_.grade_id = grade3_.id)"
" -> Hash Join (cost=465.37..241628.04 rows=10
width=143) (actual time=29.608..1661.590 rows=427 loops=1)"
" Hash Cond: (pipe0_.endfinish_id =
endfinish4_.id)"
" -> Nested Loop (cost=463.31..241625.85
rows=10 width=111) (actual time=29.531..1660.932 rows=427 loops=1)"
" -> Nested Loop
(cost=463.31..241622.11 rows=10 width=111) (actual time=29.520..1657.811
rows=427 loops=1)"
" -> Nested Loop
(cost=463.31..241610.14 rows=10 width=103) (actual time=29.508..1655.306
rows=427 loops=1)"
" Join Filter:
(pipe0_.popipe_id = popipe1_.id)"
" -> Nested Loop
(cost=0.00..240600.89 rows=12 width=96) (actual time=1.127..307.107
rows=3174 loops=1)"
" -> Nested Loop
(cost=0.00..240594.13 rows=24 width=104) (actual time=0.124..-232.727
rows=6066 loops=1)"
" -> Nested
Loop (cost=0.00..240455.39 rows=24 width=104) (actual
time=0.106..-11.779 rows=6066 loops=1)"
" ->
Nested Loop (cost=0.00..240429.94 rows=48 width=72) (actual
time=0.094..469.592 rows=7236 loops=1)"
" ->
Index Scan using t_pipe_pkey on t_pipe pipe0_ (cost=0.00..240156.45
rows=48 width=56) (actual time=0.089..175.278 rows=7236 loops=1)"
"
Filter: ((subplan) IS NULL)"
"
SubPlan"
"
-> Nested Loop Left Join (cost=0.00..24.85 rows=1 width=8) (actual
time=-0.093..-0.091 rows=1 loops=9644)"
"
-> Nested Loop (cost=0.00..16.55 rows=1 width=48) (actual
time=-0.018..-0.017 rows=1 loops=9644)"
"
-> Index Scan using t_pipe_pkey on t_pipe p (cost=0.00..8.27 rows=1
width=48) (actual time=0.003..-0.024 rows=1 loops=9644)"
"
Index Cond: (id = $0)"
"
-> Index Scan using t_generic_item_pkey on t_generic_item gi
(cost=0.00..8.27 rows=1 width=16) (actual time=0.003..-0.023 rows=1
loops=9644)"
"
Index Cond: (gi.id = $0)"
"
-> Index Scan using uk_projection_weight_grade_endfinish_actor_condtion
on t_projection pr (cost=0.00..8.28 rows=1 width=56) (actual
time=0.003..0.003 rows=0 loops=9644)"
"
Index Cond: ((pr.popipe_id = p.popipe_id) AND (pr.weight_id =
p.weight_id) AND (pr.grade_id = p.grade_id) AND (pr.endfinish_id =
p.endfinish_id) AND (pr.actor_id = gi.actor_id) AND (pr.condition_id =
p.condition_id))"
" ->
Index Scan using t_generic_item_pkey on t_generic_item pipe0_1_
(cost=0.00..5.69 rows=1 width=32) (actual time=0.002..0.003 rows=1
loops=7236)"
"
Index Cond: (pipe0_1_.id = pipe0_.id)"
" -> Index
Scan using pk_t_condition on t_condition condition7_ (cost=0.00..0.52
rows=1 width=40) (actual time=0.037..0.002 rows=1 loops=7236)"
"
Index Cond: (condition7_.id = pipe0_.condition_id)"
"
Filter: condition7_.needsprojection"
" -> Index Scan
using t_action_pkey on t_state state9_ (cost=0.00..5.77 rows=1
width=16) (actual time=-0.039..-0.039 rows=1 loops=6066)"
" Index
Cond: (state9_.id = pipe0_1_.state_id)"
" -> Index Scan using
pk_t_status on t_status status10_ (cost=0.00..0.27 rows=1 width=8)
(actual time=0.045..0.130 rows=1 loops=6066)"
" Index Cond:
(status10_.id = state9_.status_id)"
" Filter:
status10_.needsprojection"
" -> Materialize
(cost=463.31..483.53 rows=2022 width=23) (actual time=0.001..-0.357
rows=998 loops=3174)"
" -> Hash Join
(cost=81.35..461.29 rows=2022 width=23) (actual time=2.740..13.504
rows=998 loops=1)"
" Hash Cond:
(popipe1_1_.id = popipe1_.id)"
" -> Seq Scan on
t_state popipe1_1_ (cost=0.00..330.83 rows=5778 width=15) (actual
time=0.008..8.412 rows=5732 loops=1)"
" Filter:
(NOT spec)"
" -> Hash
(cost=49.49..49.49 rows=2549 width=8) (actual time=2.701..2.701
rows=2549 loops=1)"
" -> Seq
Scan on t_po_pipe popipe1_ (cost=0.00..49.49 rows=2549 width=8) (actual
time=0.010..257.753 rows=2549 loops=1)"
" -> Index Scan using pk_t_actor
on t_actor actor5_ (cost=0.00..1.18 rows=1 width=16) (actual
time=0.003..0.004 rows=1 loops=427)"
" Index Cond: (actor5_.id =
pipe0_1_.actor_id)"
" -> Index Scan using pk_t_contact on
t_contact contact6_ (cost=0.00..0.36 rows=1 width=16) (actual
time=0.004..0.005 rows=1 loops=427)"
" Index Cond: (contact6_.id =
actor5_.contact_id)"
" -> Hash (cost=1.47..1.47 rows=47 width=40)
(actual time=0.059..0.059 rows=47 loops=1)"
" -> Seq Scan on t_endfinish
endfinish4_ (cost=0.00..1.47 rows=47 width=40) (actual
time=0.016..0.033 rows=47 loops=1)"
" -> Hash (cost=1.42..1.42 rows=42 width=40)
(actual time=0.071..0.071 rows=42 loops=1)"
" -> Seq Scan on t_grade grade3_
(cost=0.00..1.42 rows=42 width=40) (actual time=0.029..0.045 rows=42
loops=1)"
" -> Index Scan using pk_t_weight on t_weight weight2_
(cost=0.00..0.60 rows=1 width=16) (actual time=0.605..0.606 rows=1
loops=427)"
" Index Cond: (weight2_.id = pipe0_.weight_id)"
"Total runtime: 2183.176 ms"

*After vacuum -- I see no improvement even after several runs*

"Sort (cost=243084.23..243084.24 rows=5 width=107) (actual
time=36649.839..36649.876 rows=158 loops=1)"
" Sort Key: (sum(pipe0_1_.numpieces)), (sum(pipe0_.numfeet))"
" Sort Method: quicksort Memory: 52kB"
" -> HashAggregate (cost=243084.08..243084.17 rows=5 width=107)
(actual time=36649.104..36649.337 rows=158 loops=1)"
" -> Nested Loop (cost=81.35..243083.89 rows=5 width=107)
(actual time=3.495..36330.092 rows=427 loops=1)"
" -> Nested Loop (cost=81.35..243080.83 rows=5 width=99)
(actual time=3.486..36325.964 rows=427 loops=1)"
" -> Nested Loop (cost=81.35..243078.18 rows=5
width=93) (actual time=3.477..36322.061 rows=427 loops=1)"
" -> Nested Loop (cost=81.35..243075.53
rows=5 width=86) (actual time=3.468..36318.062 rows=427 loops=1)"
" -> Nested Loop (cost=81.35..243073.66
rows=5 width=86) (actual time=3.457..36312.957 rows=427 loops=1)"
" -> Nested Loop
(cost=81.35..243067.67 rows=5 width=78) (actual time=3.441..36305.745
rows=427 loops=1)"
" Join Filter:
(pipe0_.popipe_id = popipe1_.id)"
" -> Nested Loop
(cost=0.00..240558.99 rows=6 width=71) (actual time=1.185..1522.885
rows=3174 loops=1)"
" -> Nested Loop
(cost=0.00..240554.20 rows=17 width=79) (actual time=0.101..440.045
rows=6066 loops=1)"
" -> Nested
Loop (cost=0.00..240455.93 rows=17 width=79) (actual
time=0.090..-131.182 rows=6066 loops=1)"
" ->
Nested Loop (cost=0.00..240430.48 rows=48 width=72) (actual
time=0.083..591.038 rows=7236 loops=1)"
" ->
Index Scan using t_pipe_pkey on t_pipe pipe0_ (cost=0.00..240156.99
rows=48 width=56) (actual time=0.078..541.958 rows=7236 loops=1)"
"
Filter: ((subplan) IS NULL)"
"
SubPlan"
"
-> Nested Loop Left Join (cost=0.00..24.85 rows=1 width=8) (actual
time=0.048..0.077 rows=1 loops=9644)"
"
-> Nested Loop (cost=0.00..16.55 rows=1 width=48) (actual
time=0.067..0.095 rows=1 loops=9644)"
"
-> Index Scan using t_pipe_pkey on t_pipe p (cost=0.00..8.27 rows=1
width=48) (actual time=0.059..0.059 rows=1 loops=9644)"
"
Index Cond: (id = $0)"
"
-> Index Scan using t_generic_item_pkey on t_generic_item gi
(cost=0.00..8.27 rows=1 width=16) (actual time=0.031..0.031 rows=1
loops=9644)"
"
Index Cond: (gi.id = $0)"
"
-> Index Scan using uk_projection_weight_grade_endfinish_actor_condtion
on t_projection pr (cost=0.00..8.28 rows=1 width=56) (actual
time=-0.075..-0.075 rows=0 loops=9644)"
"
Index Cond: ((pr.popipe_id = p.popipe_id) AND (pr.weight_id =
p.weight_id) AND (pr.grade_id = p.grade_id) AND (pr.endfinish_id =
p.endfinish_id) AND (pr.actor_id = gi.actor_id) AND (pr.condition_id =
p.condition_id))"
" ->
Index Scan using t_generic_item_pkey on t_generic_item pipe0_1_
(cost=0.00..5.69 rows=1 width=32) (actual time=-0.069..-0.067 rows=1
loops=7236)"
"
Index Cond: (pipe0_1_.id = pipe0_.id)"
" -> Index
Scan using pk_t_condition on t_condition condition7_ (cost=0.00..0.52
rows=1 width=15) (actual time=-0.139..-0.209 rows=1 loops=7236)"
"
Index Cond: (condition7_.id = pipe0_.condition_id)"
"
Filter: condition7_.needsprojection"
" -> Index Scan
using t_action_pkey on t_state state9_ (cost=0.00..5.77 rows=1
width=16) (actual time=0.132..0.091 rows=1 loops=6066)"
" Index
Cond: (state9_.id = pipe0_1_.state_id)"
" -> Index Scan using
pk_t_status on t_status status10_ (cost=0.00..0.27 rows=1 width=8)
(actual time=0.047..0.091 rows=1 loops=6066)"
" Index Cond:
(status10_.id = state9_.status_id)"
" Filter:
status10_.needsprojection"
" -> Hash Join
(cost=81.35..460.86 rows=2004 width=23) (actual time=0.092..11.790
rows=998 loops=3174)"
" Hash Cond:
(popipe1_1_.id = popipe1_.id)"
" -> Seq Scan on
t_state popipe1_1_ (cost=0.00..330.83 rows=5727 width=15) (actual
time=0.087..8.880 rows=5732 loops=3174)"
" Filter: (NOT spec)"
" -> Hash
(cost=49.49..49.49 rows=2549 width=8) (actual time=2.507..2.507
rows=2549 loops=1)"
" -> Seq Scan on
t_po_pipe popipe1_ (cost=0.00..49.49 rows=2549 width=8) (actual
time=0.015..1.208 rows=2549 loops=1)"
" -> Index Scan using pk_t_actor
on t_actor actor5_ (cost=0.00..1.18 rows=1 width=16) (actual
time=0.011..0.011 rows=1 loops=427)"
" Index Cond: (actor5_.id =
pipe0_1_.actor_id)"
" -> Index Scan using pk_t_contact on
t_contact contact6_ (cost=0.00..0.36 rows=1 width=16) (actual
time=-0.597..-0.597 rows=1 loops=427)"
" Index Cond: (contact6_.id =
actor5_.contact_id)"
" -> Index Scan using pk_t_endfinish on
t_endfinish endfinish4_ (cost=0.00..0.52 rows=1 width=15) (actual
time=0.005..0.005 rows=1 loops=427)"
" Index Cond: (endfinish4_.id =
pipe0_.endfinish_id)"
" -> Index Scan using pk_t_grade on t_grade grade3_
(cost=0.00..0.52 rows=1 width=14) (actual time=0.004..0.005 rows=1
loops=427)"
" Index Cond: (grade3_.id = pipe0_.grade_id)"
" -> Index Scan using pk_t_weight on t_weight weight2_
(cost=0.00..0.60 rows=1 width=16) (actual time=0.005..0.006 rows=1
loops=427)"
" Index Cond: (weight2_.id = pipe0_.weight_id)"
"Total runtime: 36650.609 ms"

Tom Lane wrote:
> Jason Long <mailing(dot)list(at)supernovasoftware(dot)com> writes:
>
>> I have a query that takes 2 sec if I run it from a freshly restored
>> dump. If I run a full vacuum on the database it then takes 30 seconds.
>>
>
>
>> Would someone please comment as to why I would see a 15x slow down by
>> only vacuuming the DB?
>>
>
> EXPLAIN ANALYZE of both cases might yield some insight.
>
> regards, tom lane
>