Simple test for autovacuum log messages

by gorthx

I had reason recently to suspect that autovacuum jobs weren’t being properly logged on my RDS instance. Instead of compulsively re-running “SELECT relname, last_autovacuum FROM pg_stat_user_tables” while I waited for one to happen, I set up this quick test:

connect to database and do the following:

-- verify settings
-- log_autovacuum_min_duration should be 0 ("log all") for the purposes of this test
SHOW log_autovacuum_min_duration;
-- vac messages are LOG level messages, so the default value 'warning' should suffice here
SHOW log_min_messages;

-- set up a table with a really low vac threshold
DROP TABLE IF EXISTS vac_test;
CREATE TABLE vac_test
(id serial primary key
, name text)
WITH (autovacuum_vacuum_threshold = 2, autovacuum_vacuum_scale_factor = 0)
;

-- add some data
INSERT INTO vac_test(name)
VALUES
('ankeny'),('burnside'),('couch'),('davis'),('everett'),('flanders'),('glisan'),('hoyt'),('irving')
;

-- check the stats/vac jobs
\x
SELECT * FROM pg_stat_user_tables WHERE relname = 'vac_test';

-- remove enough data to trigger an autovac
DELETE FROM vac_test WHERE id < 4;

-- check stats/vac jobs again
SELECT * FROM pg_stat_user_tables WHERE relname = 'vac_test';
\watch
-- assumes 9.3+
-- wait until you see an autovacuum job in the table
-- it'll help if you have autovacuum_naptime set to something short

Then go check the logs. You should have a helpful message about an automatic vacuum:


2014-12-07 21:01:32 PST LOG: automatic vacuum of table "postgres.public.vac_test": index scans: 1
pages: 0 removed, 1 remain
tuples: 3 removed, 6 remain
buffer usage: 60 hits, 4 misses, 4 dirtied
avg read rate: 33.422 MB/s, avg write rate: 33.422 MB/s
system usage: CPU 0.00s/0.00u sec elapsed 0.00 sec

If you don’t, well, that’s the $64,000 question, isn’t it.

Advertisements
%d bloggers like this: