Thread: autovacuum not freeing up unused space on 8.3.0
It appears (and I am open to correction) that autovacuum is not
operating correctly in 8.3.0. I have a vanilla installation where
autovacuum is enabled, and is running with all the default settings.
I have a table which is continually having rows added to it (~50/sec).
For the sake of this example I am limiting it to 20000 rows, which means
that I am continually having to remove rows (100 at a time) as I get to
20000.
When I get to 20000 rows for the first time the table disk size (using
pg_total_relation_size) is around 5MB. Since the autovacuum only kicks
in after a while I would expect it to get a little bigger (maybe 6-7MB)
and then level out as I am cycling through recovered rows.
However the table disk size continues increasing basically linearly and
when I stopped it it was approaching 40MB and heading up. During that
time I was running ANALYZE VERBOSE periodically and I could see the dead
rows increase and then drop down as the autovacuum kicked in - the
autovacuum worker process was running. It didn't seem to free any space
though. In fact a VACUUM FULL at this point didn't help a whole lot either.
I ran the same test but using manual VACUUMs every 60 seconds and the
table size leveled out at 6.6MB so it appears like a normal vacuum is
working. I changed the normal VACUUM to have the same delay parameters
(20ms) as the autovacuum and it still worked.
So it appears to me like the autovacuum is not freeing up dead rows
correctly.
I turned on logging for autovacuum and ran the same test and saw the
following messages:
LOG: automatic vacuum of table "metadb.test.transactions": index scans: 1
pages: 0 removed, 254 remain
tuples: 4082 removed, 19957 remain
system usage: CPU 0.02s/0.02u sec elapsed 1.11 sec
LOG: automatic vacuum of table "metadb.test.transactions": index scans: 1
pages: 0 removed, 271 remain
tuples: 5045 removed, 19954 remain
system usage: CPU 0.03s/0.03u sec elapsed 1.54 sec
ERROR: canceling autovacuum task
CONTEXT: automatic vacuum of table "metadb.test.transactions"
At this point I had deleted 32800 rows as can be seen from the query
below, although the logs only indicated that around 10000 rows had been
freed up.
select min(transaction_key),max(transaction_key) from test.transactions;
min | max
-------+-------
32801 | 52750
Is there anything I have missed as far as setting this up is concerned,
anything I could try? I would really rather use autovacuum than manage
the vacuums of a whole lot of tables by hand...
Thanks
Stuart
PS. Running on NetBSD 3
Stuart Brooks wrote: > ERROR: canceling autovacuum task > CONTEXT: automatic vacuum of table "metadb.test.transactions" Are these happening regularly? They indicate that something is happening on the table that collides with what autovacuum needs to do, and autovacuum defers its task. For this to happen you need to be doing ALTER TABLE or similar however; normal UPDATE/INSERT/DELETE should not cause autovacuum to cancel itself. -- Alvaro Herrera http://www.CommandPrompt.com/ PostgreSQL Replication, Consulting, Custom Development, 24x7 support
>> ERROR: canceling autovacuum task >> CONTEXT: automatic vacuum of table "metadb.test.transactions" > > Are these happening regularly? They indicate that something is > happening on the table that collides with what autovacuum needs to do, > and autovacuum defers its task. For this to happen you need to be doing > ALTER TABLE or similar however; normal UPDATE/INSERT/DELETE should not > cause autovacuum to cancel itself. > I am not using an ALTER table command but I am doing periodic ANALYZEs to evaluate the table size. Could this be causing the problem? I notice that stopping the ANALYZE calls appears to eliminate the canceled autovacuum. What concerns me is that once the size has grown, even a VACUUM FULL doesn't recover the space. Regular external VACUUMs keep the table at around 10MB but if I use autovacuum and it grows to 40MB, a VACUUM FULL will only get it down to 35MB. Is it possible that a canceled autovacuum could result in permanently lost space? Out of interest, what kind of fragmentation overhead should I expect if I have a table in which I maintain a fixed number of rows. eg. A 20000 row table which is 6MB before rows are wrapped out will obviously use a larger disk footprint as rows are added and deleted. Anyone have a rule of thumb which works for them? Thanks for the response, Stuart
On Tue, Feb 26, 2008 at 3:11 PM, Stuart Brooks <stuartb@cat.co.za> wrote: > > >> ERROR: canceling autovacuum task > >> CONTEXT: automatic vacuum of table "metadb.test.transactions" > > > > Are these happening regularly? They indicate that something is > > happening on the table that collides with what autovacuum needs to do, > > and autovacuum defers its task. For this to happen you need to be doing > > ALTER TABLE or similar however; normal UPDATE/INSERT/DELETE should not > > cause autovacuum to cancel itself. > > > I am not using an ALTER table command but I am doing periodic ANALYZEs > to evaluate the table size. Could this be causing the problem? I notice > that stopping the ANALYZE calls appears to eliminate the canceled > autovacuum. > I am trying to reproduce the case here, but could not. Can you post the table schema and the operations you are carrying out ? Is it just INSERT new rows and DELETE old rows or are there any UPDATEs too ? Are there any long running transactions open ? > What concerns me is that once the size has grown, even a VACUUM FULL > doesn't recover the space. Regular external VACUUMs keep the table at > around 10MB but if I use autovacuum and it grows to 40MB, a VACUUM FULL > will only get it down to 35MB. Is it possible that a canceled autovacuum > could result in permanently lost space? > AFAIK it should not. Can you also post VACUUM FULL VERBOSE output ? Thanks, Pavan -- Pavan Deolasee EnterpriseDB http://www.enterprisedb.com
>> >> ERROR: canceling autovacuum task >> >> CONTEXT: automatic vacuum of table "metadb.test.transactions" >> > >> > Are these happening regularly? They indicate that something is >> > happening on the table that collides with what autovacuum needs to do, >> > and autovacuum defers its task. For this to happen you need to be doing >> > ALTER TABLE or similar however; normal UPDATE/INSERT/DELETE should not >> > cause autovacuum to cancel itself. >> > >> I am not using an ALTER table command but I am doing periodic ANALYZEs >> to evaluate the table size. Could this be causing the problem? I notice >> that stopping the ANALYZE calls appears to eliminate the canceled >> autovacuum. >> > > > I am trying to reproduce the case here, but could not. Can you post the table > schema and the operations you are carrying out ? Is it just INSERT new rows > and DELETE old rows or are there any UPDATEs too ? Are there any long > running transactions open ? > It'll take a few minutes but I'll try and get the information to you. A summary is: Process 1: - writing 50 rows/second, 1 row/transaction. - every so often delete 100 rows Process 2: - running ANALYZE VERBOSE and pg_total_relation_size every second The result is that autovacuum appears to be canceled. I was incorrect about autovacuum not recovering. Once I stop the ANALYZEs it appears to stabilise and recover some of the space after a little while. At that point a VACUUM FULL does help, and recovers quite a bit of space. I'll run through this again here and provide you with logs and VACUUM printouts. >> What concerns me is that once the size has grown, even a VACUUM FULL >> doesn't recover the space. Regular external VACUUMs keep the table at >> around 10MB but if I use autovacuum and it grows to 40MB, a VACUUM FULL >> will only get it down to 35MB. Is it possible that a canceled autovacuum >> could result in permanently lost space? >> > > AFAIK it should not. Can you also post VACUUM FULL VERBOSE output ? Thanks for your help, Stuart
"Stuart Brooks" <stuartb@cat.co.za> writes: > It'll take a few minutes but I'll try and get the information to you. A summary > is: > > Process 1: > - writing 50 rows/second, 1 row/transaction. > - every so often delete 100 rows > > Process 2: > - running ANALYZE VERBOSE and pg_total_relation_size every second You'll probably have to vacuum pg_statistics as well then. -- Gregory Stark EnterpriseDB http://www.enterprisedb.com Get trained by Bruce Momjian - ask me about EnterpriseDB's PostgreSQL training!
Stuart Brooks wrote: > I am not using an ALTER table command but I am doing periodic ANALYZEs > to evaluate the table size. Could this be causing the problem? I notice > that stopping the ANALYZE calls appears to eliminate the canceled > autovacuum. Why were you running ANALYZE on the first place? If it's just to see how many dead space there is, I suggest you peek into pg_stat_user_tables instead, which is less invasive. Autovacuum itself should run ANALYZEs as needed (and you can, of course, tune it if you feel it's not frequent enough in the default configuration). -- Alvaro Herrera http://www.CommandPrompt.com/ PostgreSQL Replication, Consulting, Custom Development, 24x7 support
>> It'll take a few minutes but I'll try and get the information to you. A summary >> is: >> >> Process 1: >> - writing 50 rows/second, 1 row/transaction. >> - every so often delete 100 rows >> >> Process 2: >> - running ANALYZE VERBOSE and pg_total_relation_size every second >> > > You'll probably have to vacuum pg_statistics as well then. > > I presume because of the frequent ANALYZEs? In my real-world application I won't be running ANALYZE manually like this. I am only using it as a quick hack to get a picture of the dead rows in the various tables so I could get a feel for what was happening, and it seems that this is what is causing a conflict with the autovacuum...
>> What concerns me is that once the size has grown, even a VACUUM FULL
>> doesn't recover the space. Regular external VACUUMs keep the table at
>> around 10MB but if I use autovacuum and it grows to 40MB, a VACUUM FULL
>> will only get it down to 35MB. Is it possible that a canceled autovacuum
>> could result in permanently lost space?
>>
>>
>
> AFAIK it should not. Can you also post VACUUM FULL VERBOSE output ?
>
>
I have attached the vacuum output below, along with the table definition
and a before and after of the table size. In this case a full vacuum (on
the 20000 row table) took it down from 34MB to 21MB. Maybe you can tell
me if this is reasonable, bearing in mind that after inserting 20000
rows at the start the size is about 6MB, and under normal vacuuming
conditions it sits around 10-12MB. This is better than the last time I
ran it though.
Thanks for the help,
Stuart
metadb=> \d test.transactions
Table "test.transactions"
Column | Type | Modifiers
-----------------+--------------------------------+-----------------------------------------------------------------------------
transaction_key | bigint | not null default
nextval('test.transactions_transaction_key_seq'::regclass)
time | timestamp(6) without time zone | not null
cashier | text | not null
till | integer | not null
ring | integer | not null
ev_tstamp | integer | not null
ev_id | integer | not null
camera | integer | not null
Indexes:
"transactions_pkey" PRIMARY KEY, btree (transaction_key)
"transactions_camera_index" btree (camera)
"transactions_cashier_index" btree (cashier, transaction_key)
"transactions_event_index" btree (ring, ev_tstamp, ev_id)
"transactions_time_index" btree ("time", transaction_key)
metadb=> select pg_total_relation_size('test.transactions');
pg_total_relation_size
------------------------
34242560
(1 row)
metadb=> vacuum full verbose test.transactions;
INFO: vacuuming "test.transactions"
INFO: "transactions": found 0 removable, 19996 nonremovable row versions in 1592 pages
DETAIL: 0 dead row versions cannot be removed yet.
Nonremovable row versions range from 64 to 68 bytes long.
There were 2109 unused item pointers.
Total free space (including removable row versions) is 10199944 bytes.
1416 pages are or will become empty, including 0 at the end of the table.
1347 pages containing 10194740 free bytes are potential move destinations.
CPU 0.00s/0.01u sec elapsed 0.24 sec.
INFO: index "transactions_pkey" now contains 19996 row versions in 100 pages
DETAIL: 0 index row versions were removed.
42 index pages have been deleted, 42 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO: index "transactions_event_index" now contains 19996 row versions in 215 pages
DETAIL: 0 index row versions were removed.
93 index pages have been deleted, 93 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.05 sec.
INFO: index "transactions_camera_index" now contains 19996 row versions in 146 pages
DETAIL: 0 index row versions were removed.
56 index pages have been deleted, 56 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.02 sec.
INFO: index "transactions_cashier_index" now contains 19996 row versions in 429 pages
DETAIL: 0 index row versions were removed.
290 index pages have been deleted, 290 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.05 sec.
INFO: index "transactions_time_index" now contains 19996 row versions in 1496 pages
DETAIL: 115518 index row versions were removed.
1412 index pages have been deleted, 1412 are currently reusable.
CPU 0.00s/0.11u sec elapsed 4.28 sec.
INFO: "transactions": moved 19996 row versions, truncated 1592 to 208 pages
DETAIL: CPU 0.12s/0.73u sec elapsed 20.75 sec.
INFO: index "transactions_pkey" now contains 19996 row versions in 112 pages
DETAIL: 19996 index row versions were removed.
0 index pages have been deleted, 0 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.06 sec.
INFO: index "transactions_event_index" now contains 19996 row versions in 215 pages
DETAIL: 19996 index row versions were removed.
77 index pages have been deleted, 77 are currently reusable.
CPU 0.00s/0.01u sec elapsed 0.04 sec.
INFO: index "transactions_camera_index" now contains 19996 row versions in 152 pages
DETAIL: 19996 index row versions were removed.
58 index pages have been deleted, 58 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.12 sec.
INFO: index "transactions_cashier_index" now contains 19996 row versions in 429 pages
DETAIL: 19996 index row versions were removed.
273 index pages have been deleted, 273 are currently reusable.
CPU 0.00s/0.01u sec elapsed 0.13 sec.
INFO: index "transactions_time_index" now contains 19996 row versions in 1496 pages
DETAIL: 19996 index row versions were removed.
1339 index pages have been deleted, 1339 are currently reusable.
CPU 0.00s/0.01u sec elapsed 0.30 sec.
INFO: vacuuming "pg_toast.pg_toast_18356"
INFO: "pg_toast_18356": found 0 removable, 0 nonremovable row versions in 0 pages
DETAIL: 0 dead row versions cannot be removed yet.
Nonremovable row versions range from 0 to 0 bytes long.
There were 0 unused item pointers.
Total free space (including removable row versions) is 0 bytes.
0 pages are or will become empty, including 0 at the end of the table.
0 pages containing 0 free bytes are potential move destinations.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO: index "pg_toast_18356_index" now contains 0 row versions in 1 pages
DETAIL: 0 index pages have been deleted, 0 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
VACUUM
metadb=> select pg_total_relation_size('test.transactions');
pg_total_relation_size
------------------------
21405696
(1 row)
Stuart Brooks <stuartb@cat.co.za> writes:
> Process 2:
> - running ANALYZE VERBOSE and pg_total_relation_size every second
> The result is that autovacuum appears to be canceled.
Yes, that will pretty much guarantee that an autovacuum is never able to
complete...
> What concerns me is that once the size has grown, even a VACUUM FULL
> doesn't recover the space. Regular external VACUUMs keep the table at
> around 10MB but if I use autovacuum and it grows to 40MB, a VACUUM FULL
> will only get it down to 35MB. Is it possible that a canceled autovacuum
> could result in permanently lost space?
Are you measuring index as well as table size? VACUUM FULL is no good
at compacting indexes.
regards, tom lane
Stuart Brooks wrote: > It'll take a few minutes but I'll try and get the information to you. A > summary is: > > Process 1: > - writing 50 rows/second, 1 row/transaction. > - every so often delete 100 rows > > Process 2: > - running ANALYZE VERBOSE and pg_total_relation_size every second > > The result is that autovacuum appears to be canceled. Why do have a second process that does an analyze every second? That seems like overkill and also if you let autovacuum do it, then it will play better with vacuums when needed. If you need autovacuum to analyze more aggressively on this table you can change the table specific thresholds. I know that before 8.3 autovacuum wouldn't always keep up on tables like this, but as of 8.3 with multiple simultaneous workers etc, it should be much better.
>> Process 2: >> - running ANALYZE VERBOSE and pg_total_relation_size every second >> > > >> The result is that autovacuum appears to be canceled. >> > > Yes, that will pretty much guarantee that an autovacuum is never able to > complete... > > That's what I figured. Since I won't be running ANALYZE under normal circumstances this should all work fine... >> What concerns me is that once the size has grown, even a VACUUM FULL >> doesn't recover the space. Regular external VACUUMs keep the table at >> around 10MB but if I use autovacuum and it grows to 40MB, a VACUUM FULL >> will only get it down to 35MB. Is it possible that a canceled autovacuum >> could result in permanently lost space? >> > > Are you measuring index as well as table size? VACUUM FULL is no good > at compacting indexes. > > I am measuring pg_total_relation_size which I believe includes indexes. How does one go about compacting indexes if a VACUUM doesn't do the trick? I see that a recommendation is to drop and recreate the indexes. If one has a system running 24-7, then this might not be feasible. Thanks Stuart
Stuart Brooks wrote: >> Are you measuring index as well as table size? VACUUM FULL is no good >> at compacting indexes. >> > I am measuring pg_total_relation_size which I believe includes indexes. > How does one go about compacting indexes if a VACUUM doesn't do the > trick? I see that a recommendation is to drop and recreate the indexes. > If one has a system running 24-7, then this might not be feasible. The simplest way is to use REINDEX INDEX, but it needs a strong lock. The more complex way is to do CREATE INDEX CONCURRENTLY index_2 ... -- duplicating the original index DROP INDEX index; which does not need to grab a lock for a long period. -- Alvaro Herrera http://www.CommandPrompt.com/ The PostgreSQL Company - Command Prompt, Inc.
>>> Are you measuring index as well as table size? VACUUM FULL is no good >>> at compacting indexes. >>> >>> >> I am measuring pg_total_relation_size which I believe includes indexes. >> How does one go about compacting indexes if a VACUUM doesn't do the >> trick? I see that a recommendation is to drop and recreate the indexes. >> If one has a system running 24-7, then this might not be feasible. >> > > The simplest way is to use REINDEX INDEX, but it needs a strong lock. > > The more complex way is to do > > CREATE INDEX CONCURRENTLY index_2 ... -- duplicating the original index > DROP INDEX index; > > which does not need to grab a lock for a long period. > > That does the trick and gets the table size down to what I'd expect from a 'clean' run. Now I just need to run a few tests to work out what a stable size is for a table with this many rows. Thanks for all the help tracking this down. It's really appreciated :) Kind regards Stuart