Re: Vacuuming static tables.

On Wed, May 10, 2006 1:59 pm, Alan Hodgson said:
> On May 10, 2006 10:54 am, "Daniel T. Staal" <DStaal@usa.net> wrote:
>> Then the question is why doesn't running it twice in a row speed it up?
>>  (When I plug in *exactly* the same values.)
>
> Yeah, I don't understand that.  You might see what else is running on the
>  database at the same time as the problem occurs?  When you vacuum, do
> you vacuum only this table, or is the vacuum perhaps fixing another
> problem that is coincidental to causing this query to be slow?

I don't know.  It is not a momentary thing, though: I spent half an hour
looking over different things before finding this table the first time it
came up.

The weekly vacuums do the entire database, but for looking into this I've
been running vacuum on that table in particular.

> Post the output of 2 subsequent explain analyzes the next time the
> problem shows up, and then run the vacuum and post a third.  I'm sure
> someone smarter than me will spot something.

You are in luck...  I've got several of those lying around.  ;)  I'm not
sure exactly when each one was from though.

Since it is going to be your next question, the table I vacuum is 'ibox'.

However, here's the first one I ran when it was slow:
---
 Unique  (cost=13908.06..13908.10 rows=7 width=24) (actual
time=14802.351..14802.551 rows=83 loops=1)
   ->  Sort  (cost=13908.06..13908.08 rows=7 width=24) (actual
time=14802.348..14802.402 rows=88 loops=1)
         Sort Key: ibx
         ->  Append  (cost=8.01..13907.97 rows=7 width=24) (actual
time=158.325..14801.330 rows=88 loops=1)
               ->  Nested Loop  (cost=8.01..2490.68 rows=1 width=24)
(actual time=158.323..3620.643 rows=40 loops=1)
                     ->  Nested Loop  (cost=4.00..2482.65 rows=1 width=24)
(actual time=158.079..3367.516 rows=41 loops=1)
                           ->  Index Scan using partner_pkey on partner a
(cost=0.00..33.25 rows=305 width=48) (actual
time=0.126..2.338 rows=309 loops=1)
                                 Filter: (pending = 0)
                           ->  Bitmap Heap Scan on ibox c
(cost=4.00..8.02 rows=1 width=24) (actual
time=10.885..10.885 rows=0 loops=309)
                                 Recheck Cond: ("outer".pibx = c.ibx)
                                 Filter: ((privilege > 1) AND (gsb =
'10119'::bpchar))
                                 ->  Bitmap Index Scan on ibox_pkey
(cost=0.00..4.00 rows=1 width=0) (actual
time=10.860..10.860 rows=2 loops=309)
                                       Index Cond: ("outer".pibx = c.ibx)
                     ->  Bitmap Heap Scan on ibox b  (cost=4.00..8.02
rows=1 width=24) (actual time=6.156..6.157 rows=1
loops=41)
                           Recheck Cond: ("outer".ibx = b.ibx)
                           Filter: (gsb <> '10119'::bpchar)
                           ->  Bitmap Index Scan on ibox_pkey
(cost=0.00..4.00 rows=1 width=0) (actual
time=6.122..6.122 rows=2 loops=41)
                                 Index Cond: ("outer".ibx = b.ibx)
               ->  Nested Loop  (cost=8.01..2466.66 rows=1 width=24)
(actual time=10.560..2038.229 rows=20 loops=1)
                     ->  Nested Loop  (cost=4.00..2458.63 rows=1 width=24)
(actual time=10.484..1918.852 rows=20 loops=1)
                           ->  Seq Scan on partner a  (cost=0.00..9.99
rows=305 width=48) (actual time=0.011..0.948
rows=309 loops=1)
                                 Filter: (pending = 0)
                           ->  Bitmap Heap Scan on ibox b
(cost=4.00..8.02 rows=1 width=24) (actual
time=6.202..6.202 rows=0 loops=309)
                                 Recheck Cond: ("outer".ibx = b.ibx)
                                 Filter: (gsb = '10119'::bpchar)
                                 ->  Bitmap Index Scan on ibox_pkey
(cost=0.00..4.00 rows=1 width=0) (actual
time=6.182..6.182 rows=2 loops=309)
                                       Index Cond: ("outer".ibx = b.ibx)
                     ->  Bitmap Heap Scan on ibox c  (cost=4.00..8.02
rows=1 width=24) (actual time=5.950..5.952 rows=1
loops=20)
                           Recheck Cond: ("outer".pibx = c.ibx)
                           Filter: (privilege > 1)
                           ->  Bitmap Index Scan on ibox_pkey
(cost=0.00..4.00 rows=1 width=0) (actual
time=5.916..5.916 rows=2 loops=20)
                                 Index Cond: ("outer".pibx = c.ibx)
               ->  Nested Loop  (cost=4.00..8950.56 rows=5 width=24)
(actual time=4220.658..9142.234 rows=28 loops=1)
                     ->  Seq Scan on iboxcc a  (cost=0.00..39.10 rows=1110
width=48) (actual time=0.035..2.731 rows=1111
loops=1)
                     ->  Bitmap Heap Scan on ibox b  (cost=4.00..8.02
rows=1 width=24) (actual time=8.222..8.222 rows=0
loops=1111)
                           Recheck Cond: ("outer".ibx = b.ibx)
                           Filter: (gsb = '10119'::bpchar)
                           ->  Bitmap Index Scan on ibox_pkey
(cost=0.00..4.00 rows=1 width=0) (actual
time=8.213..8.213 rows=2 loops=1111)
                                 Index Cond: ("outer".ibx = b.ibx)
 Total runtime: 14803.022 ms
(2462 rows)
---

Here's one I ran a moment later, when I realized that 'explain analyze
verbose' gives *way* more info than I knew what to do with...:

------------------------------------------------------------------------------------------------------------------------------------------------------------
 Unique  (cost=13908.06..13908.10 rows=7 width=24) (actual
time=15758.058..15758.242 rows=83 loops=1)
   ->  Sort  (cost=13908.06..13908.08 rows=7 width=24) (actual
time=15758.055..15758.104 rows=88 loops=1)
         Sort Key: ibx
         ->  Append  (cost=8.01..13907.97 rows=7 width=24) (actual
time=160.986..15756.934 rows=88 loops=1)
               ->  Nested Loop  (cost=8.01..2490.68 rows=1 width=24)
(actual time=160.984..4061.117 rows=40 loops=1)
                     ->  Nested Loop  (cost=4.00..2482.65 rows=1 width=24)
(actual time=160.663..3796.389 rows=41 loops=1)
                           ->  Index Scan using partner_pkey on partner a
(cost=0.00..33.25 rows=305 width=48) (actual
time=0.067..5.126 rows=309 loops=1)
                                 Filter: (pending = 0)
                           ->  Bitmap Heap Scan on ibox c
(cost=4.00..8.02 rows=1 width=24) (actual
time=12.262..12.263 rows=0 loops=309)
                                 Recheck Cond: ("outer".pibx = c.ibx)
                                 Filter: ((privilege > 1) AND (gsb =
'10119'::bpchar))
                                 ->  Bitmap Index Scan on ibox_pkey
(cost=0.00..4.00 rows=1 width=0) (actual
time=12.227..12.227 rows=2 loops=309)
                                       Index Cond: ("outer".pibx = c.ibx)
                     ->  Bitmap Heap Scan on ibox b  (cost=4.00..8.02
rows=1 width=24) (actual time=6.435..6.436 rows=1
loops=41)
                           Recheck Cond: ("outer".ibx = b.ibx)
                           Filter: (gsb <> '10119'::bpchar)
                           ->  Bitmap Index Scan on ibox_pkey
(cost=0.00..4.00 rows=1 width=0) (actual
time=6.389..6.389 rows=2 loops=41)
                                 Index Cond: ("outer".ibx = b.ibx)
               ->  Nested Loop  (cost=8.01..2466.66 rows=1 width=24)
(actual time=10.593..2104.946 rows=20 loops=1)
                     ->  Nested Loop  (cost=4.00..2458.63 rows=1 width=24)
(actual time=10.478..1981.282 rows=20 loops=1)
                           ->  Seq Scan on partner a  (cost=0.00..9.99
rows=305 width=48) (actual time=0.038..1.147
rows=309 loops=1)
                                 Filter: (pending = 0)
                           ->  Bitmap Heap Scan on ibox b
(cost=4.00..8.02 rows=1 width=24) (actual
time=6.403..6.403 rows=0 loops=309)
                                 Recheck Cond: ("outer".ibx = b.ibx)
                                 Filter: (gsb = '10119'::bpchar)
                                 ->  Bitmap Index Scan on ibox_pkey
(cost=0.00..4.00 rows=1 width=0) (actual
time=6.375..6.375 rows=2 loops=309)
                                       Index Cond: ("outer".ibx = b.ibx)
                     ->  Bitmap Heap Scan on ibox c  (cost=4.00..8.02
rows=1 width=24) (actual time=6.160..6.163 rows=1
loops=20)
                           Recheck Cond: ("outer".pibx = c.ibx)
                           Filter: (privilege > 1)
                           ->  Bitmap Index Scan on ibox_pkey
(cost=0.00..4.00 rows=1 width=0) (actual
time=6.115..6.115 rows=2 loops=20)
                                 Index Cond: ("outer".pibx = c.ibx)
               ->  Nested Loop  (cost=4.00..8950.56 rows=5 width=24)
(actual time=4383.254..9590.628 rows=28 loops=1)
                     ->  Seq Scan on iboxcc a  (cost=0.00..39.10 rows=1110
width=48) (actual time=0.050..3.052 rows=1111
loops=1)
                     ->  Bitmap Heap Scan on ibox b  (cost=4.00..8.02
rows=1 width=24) (actual time=8.623..8.624 rows=0
loops=1111)
                           Recheck Cond: ("outer".ibx = b.ibx)
                           Filter: (gsb = '10119'::bpchar)
                           ->  Bitmap Index Scan on ibox_pkey
(cost=0.00..4.00 rows=1 width=0) (actual
time=8.609..8.609 rows=2 loops=1111)
                                 Index Cond: ("outer".ibx = b.ibx)
 Total runtime: 15758.727 ms
(40 rows)
---

And here it is just after one of the vacuums.  (I'm not sure if it is the
same day as the two right before, but they are all very similar.):

------------------------------------------------------------------------------------------------------------------------------------------------------------
 Unique  (cost=15802.78..15802.95 rows=34 width=24) (actual
time=78.575..78.771 rows=83 loops=1)
   ->  Sort  (cost=15802.78..15802.86 rows=34 width=24) (actual
time=78.572..78.626 rows=88 loops=1)
         Sort Key: ibx
         ->  Append  (cost=10.01..15801.91 rows=34 width=24) (actual
time=2.955..77.927 rows=88 loops=1)
               ->  Nested Loop  (cost=10.01..2841.86 rows=2 width=24)
(actual time=2.953..24.663 rows=40 loops=1)
                     ->  Nested Loop  (cost=5.00..2823.81 rows=2 width=24)
(actual time=2.846..20.612 rows=41 loops=1)
                           ->  Index Scan using partner_pkey on partner a
(cost=0.00..33.27 rows=309 width=48) (actual
time=0.125..1.499 rows=309 loops=1)
                                 Filter: (pending = 0)
                           ->  Bitmap Heap Scan on ibox c
(cost=5.00..9.02 rows=1 width=24) (actual
time=0.058..0.058 rows=0 loops=309)
                                 Recheck Cond: ("outer".pibx = c.ibx)
                                 Filter: ((privilege > 1) AND (gsb =
'10119'::bpchar))
                                 ->  Bitmap Index Scan on ibox_pkey
(cost=0.00..5.00 rows=1 width=0) (actual
time=0.045..0.045 rows=1 loops=309)
                                       Index Cond: ("outer".pibx = c.ibx)
                     ->  Bitmap Heap Scan on ibox b  (cost=5.00..9.02
rows=1 width=24) (actual time=0.092..0.093 rows=1
loops=41)
                           Recheck Cond: ("outer".ibx = b.ibx)
                           Filter: (gsb <> '10119'::bpchar)
                           ->  Bitmap Index Scan on ibox_pkey
(cost=0.00..5.00 rows=1 width=0) (actual
time=0.072..0.072 rows=1 loops=41)
                                 Index Cond: ("outer".ibx = b.ibx)
               ->  Nested Loop  (cost=10.01..2872.03 rows=2 width=24)
(actual time=0.301..16.010 rows=20 loops=1)
                     ->  Nested Loop  (cost=5.00..2799.80 rows=8 width=24)
(actual time=0.246..14.859 rows=20 loops=1)
                           ->  Seq Scan on partner a  (cost=0.00..10.04
rows=309 width=48) (actual time=0.010..0.600
rows=309 loops=1)
                                 Filter: (pending = 0)
                           ->  Bitmap Heap Scan on ibox b
(cost=5.00..9.02 rows=1 width=24) (actual
time=0.043..0.043 rows=0 loops=309)
                                 Recheck Cond: ("outer".ibx = b.ibx)
                                 Filter: (gsb = '10119'::bpchar)
                                 ->  Bitmap Index Scan on ibox_pkey
(cost=0.00..5.00 rows=1 width=0) (actual
time=0.033..0.033 rows=1 loops=309)
                                       Index Cond: ("outer".ibx = b.ibx)
                     ->  Bitmap Heap Scan on ibox c  (cost=5.00..9.02
rows=1 width=24) (actual time=0.051..0.052 rows=1
loops=20)
                           Recheck Cond: ("outer".pibx = c.ibx)
                           Filter: (privilege > 1)
                           ->  Bitmap Index Scan on ibox_pkey
(cost=0.00..5.00 rows=1 width=0) (actual
time=0.038..0.038 rows=1 loops=20)
                                 Index Cond: ("outer".pibx = c.ibx)
               ->  Nested Loop  (cost=5.00..10087.69 rows=30 width=24)
(actual time=15.439..37.133 rows=28 loops=1)
                     ->  Seq Scan on iboxcc a  (cost=0.00..39.13 rows=1113
width=48) (actual time=0.054..2.211 rows=1113
loops=1)
                     ->  Bitmap Heap Scan on ibox b  (cost=5.00..9.02
rows=1 width=24) (actual time=0.028..0.028 rows=0
loops=1113)
                           Recheck Cond: ("outer".ibx = b.ibx)
                           Filter: (gsb = '10119'::bpchar)
                           ->  Bitmap Index Scan on ibox_pkey
(cost=0.00..5.00 rows=1 width=0) (actual
time=0.023..0.023 rows=1 loops=1113)
                                 Index Cond: ("outer".ibx = b.ibx)
 Total runtime: 79.269 ms
(40 rows)
---

I have the query written to file to create these, so they are all off
exactly the same query.

Daniel T. Staal

---------------------------------------------------------------

This email copyright the author.  Unless otherwise noted, you
are expressly allowed to retransmit, quote, or otherwise use
the contents for non-commercial purposes.  This copyright will
expire 5 years after the author's death, or in 30 years,
whichever is longer, unless such a period is in excess of
local copyright law.
---------------------------------------------------------------