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

---------------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend

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

---------------------------(end of broadcast)---------------------------
TIP 9: In versions below 8.0, the planner will ignore your desire to
choose an index scan if your joining column's datatypes do not
match

>> 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


---------------------------(end of broadcast)---------------------------
TIP 4: Have you searched our list archives?

http://archives.postgresql.org/

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

---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings

>> >> 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


---------------------------(end of broadcast)---------------------------
TIP 4: Have you searched our list archives?

http://archives.postgresql.org/

"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!

---------------------------(end of broadcast)---------------------------
TIP 9: In versions below 8.0, the planner will ignore your desire to
choose an index scan if your joining column's datatypes do not
match

>> 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...

---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@postgresql.org so that your
message can get through to the mailing list cleanly

>> 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'::r egclass)
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)


---------------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend

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

---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings

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.

---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings