Thread: Vacuuming static tables.
I'm just trying to hunt down the reason for some odd behavior I'm noticing here. We vacuum our database once a week, which is good enough for most things. However, there is one query that gets run interactively that slows down considerably over the course of a week: One memorable week it was taking over 15 seconds to run. Just after a vacuum it takes around 0.7 seconds. The odd thing is that while this is a moderately complex query; three tables, multiple 'union's, etc, *all* the tables involved are fairly static. The biggest (and the one I've confirmed makes the difference when I vacuum it) would be having a busy week if there were ten inserts. Deletes are even rarer. Other tables in this database have several times that traffic a minute. So, I'm just wondering if there is a way to figure out why vacuuming that table in particular makes such a difference. It's not used that often, but where it is used a person is waiting for the results. (In contrast to most of our database, which interacts with automated processes for the most part.) Of course, the solution is to vacuum it more often. I'm just wondering *why* it matters. Any ideas on where to look? We stay away from foreign keys in this database... 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. ---------------------------------------------------------------
On May 10, 2006 08:48 am, "Daniel T. Staal" <DStaal@usa.net> wrote: > However, there is one query that gets run interactively that slows down > considerably over the course of a week: One memorable week it was taking > over 15 seconds to run. Just after a vacuum it takes around 0.7 seconds. Vacuuming has the side effect of loading the table and indexes into your OS cache (assuming you have enough RAM). The subsequent query then doesn't have to go to disk for the contents. 15 seconds -> .7 seconds sounds very much like a disk vs. cache speed difference. Unless you notice the query plan changing in EXPLAIN ANALYZE after running a vacuum analyze, I think this is the most likely explanation; your query speed varies depending how much of the data is already in cache. -- No long, complicated contracts. No actuarial tables to pore over. Social Security operates on a very simple principle: the politicians take your money from you and squander it "
On Wed, May 10, 2006 12:50 pm, Alan Hodgson said: > On May 10, 2006 08:48 am, "Daniel T. Staal" <DStaal@usa.net> wrote: >> However, there is one query that gets run interactively that slows down >> considerably over the course of a week: One memorable week it was >> taking over 15 seconds to run. Just after a vacuum it takes around 0.7 >> seconds. > > Vacuuming has the side effect of loading the table and indexes into your > OS cache (assuming you have enough RAM). The subsequent query then > doesn't have to go to disk for the contents. 15 seconds -> .7 seconds > sounds very much like a disk vs. cache speed difference. > > Unless you notice the query plan changing in EXPLAIN ANALYZE after > running a vacuum analyze, I think this is the most likely explanation; > your query speed varies depending how much of the data is already in > cache. Then the question is why doesn't running it twice in a row speed it up? (When I plug in *exactly* the same values.) If I vacuum one day, normally when I come in in the morning it takes about twice as long as the minimum time. The 15 seconds was the exceptional value: the one that brought this to my attention. (Because waiting 20+ seconds for a web page that normally takes only one or two is noticable. ;)) That was probably a busy week for that table: we added a big new customer, and this table tracks customer 'mailboxes'. So there may have been 10 inserts or so that week. Still, that's probably a good answer, and at least part of what I am seeing. (The query plan doesn't change. I had already checked that. The only thing that changes is the estimated time and costs of each step.) 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. ---------------------------------------------------------------
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 cannot think how else vacuum could make any difference to a rarely updated table, though. 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. -- "It's not a war on drugs, it's a war on personal freedom. Keep that in mind at all times."
On 5/10/06 1:54 PM, "Daniel T. Staal" <DStaal@usa.net> wrote: > On Wed, May 10, 2006 12:50 pm, Alan Hodgson said: >> On May 10, 2006 08:48 am, "Daniel T. Staal" <DStaal@usa.net> wrote: >>> However, there is one query that gets run interactively that slows down >>> considerably over the course of a week: One memorable week it was >>> taking over 15 seconds to run. Just after a vacuum it takes around 0.7 >>> seconds. >> >> Vacuuming has the side effect of loading the table and indexes into your >> OS cache (assuming you have enough RAM). The subsequent query then >> doesn't have to go to disk for the contents. 15 seconds -> .7 seconds >> sounds very much like a disk vs. cache speed difference. >> >> Unless you notice the query plan changing in EXPLAIN ANALYZE after >> running a vacuum analyze, I think this is the most likely explanation; >> your query speed varies depending how much of the data is already in >> cache. > > Then the question is why doesn't running it twice in a row speed it up? > (When I plug in *exactly* the same values.) > > If I vacuum one day, normally when I come in in the morning it takes about > twice as long as the minimum time. The 15 seconds was the exceptional > value: the one that brought this to my attention. (Because waiting 20+ > seconds for a web page that normally takes only one or two is noticable. > ;)) That was probably a busy week for that table: we added a big new > customer, and this table tracks customer 'mailboxes'. So there may have > been 10 inserts or so that week. > > Still, that's probably a good answer, and at least part of what I am seeing. > > (The query plan doesn't change. I had already checked that. The only > thing that changes is the estimated time and costs of each step.) My guess is that you are going to have to send some explain analyze output for the minimum time case and then for something like the "maximum time" case so that folks can see what is going on. Sean
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.
---------------------------------------------------------------
On May 10, 2006 11:24 am, "Daniel T. Staal" <DStaal@usa.net> wrote: > > I have the query written to file to create these, so they are all off > exactly the same query. > > Daniel T. Staal Well, I don't see what the problem is, but as you said, it's executing exactly the same plan, so I think it has to to be a disk access issue; either a caching effect or something else is hammering the disk during the slow query. Perhaps someone more knowledgeable will have some insight. -- "There are more instances of the abridgment of the freedom of the people by the gradual and silent encroachment of those in power, than by violent and sudden usurpation." -- James Madison
"Daniel T. Staal" <DStaal@usa.net> writes:
> The odd thing is that while this is a moderately complex query; three
> tables, multiple 'union's, etc, *all* the tables involved are fairly
> static. The biggest (and the one I've confirmed makes the difference when
> I vacuum it) would be having a busy week if there were ten inserts.
> Deletes are even rarer.
What about updates? Updating an existing row generates vacuumable trash...
regards, tom lane