Re: AutoVacuum Behaviour Question

Bruce McAlister wrote:

> I will run with DEBUG2 for a while and see if my output looks anything
> like this :)

I've been running in DEBUG2 mode for a couple days now and I can see the
extra information being logged into the log file, but it looks like the
autovacuum is not actually starting, it does not look anything like the
output you showed me, ie, what it is supposed to look like. Here's an
excerpt of our log for the last 15 - 20 minutes.

Jun 28 07:56:01 bfiedb01 postgres[17003]: [ID 748848 local0.debug]
[45371-1] 17003 DEBUG: autovacuum: processing database "blueface-crm"
Jun 28 07:57:01 bfiedb01 postgres[17025]: [ID 748848 local0.debug]
[45371-1] 17025 DEBUG: autovacuum: processing database "blueface-crm"
Jun 28 07:58:01 bfiedb01 postgres[17047]: [ID 748848 local0.debug]
[45371-1] 17047 DEBUG: autovacuum: processing database "blueface-crm"
Jun 28 07:58:41 bfiedb01 postgres[29224]: [ID 748848 local0.debug]
[5390-1] 29224 DEBUG: checkpoint starting
Jun 28 07:58:41 bfiedb01 postgres[29224]: [ID 748848 local0.debug]
[5391-1] 29224 DEBUG: checkpoint complete; 0 transaction log file(s)
added, 0 removed, 0 recycled
Jun 28 07:59:01 bfiedb01 postgres[17069]: [ID 748848 local0.debug]
[45371-1] 17069 DEBUG: autovacuum: processing database "blueface-crm"
Jun 28 08:00:01 bfiedb01 postgres[29121]: [ID 748848 local0.debug]
[45371-1] 29121 DEBUG: forked new backend, pid=17098 socket=9
Jun 28 08:00:01 bfiedb01 postgres[17099]: [ID 748848 local0.debug]
[45372-1] 17099 DEBUG: autovacuum: processing database "blueface-crm"
Jun 28 08:00:01 bfiedb01 postgres[29121]: [ID 748848 local0.debug]
[45372-1] 29121 DEBUG: server process (PID 17098) exited with exit
code 0
Jun 28 08:00:01 bfiedb01 postgres[29121]: [ID 748848 local0.debug]
[45373-1] 29121 DEBUG: forked new backend, pid=17100 socket=9
Jun 28 08:00:01 bfiedb01 postgres[29121]: [ID 748848 local0.debug]
[45374-1] 29121 DEBUG: server process (PID 17100) exited with exit
code 0
Jun 28 08:01:01 bfiedb01 postgres[17122]: [ID 748848 local0.debug]
[45375-1] 17122 DEBUG: autovacuum: processing database "blueface-crm"
Jun 28 08:02:01 bfiedb01 postgres[17144]: [ID 748848 local0.debug]
[45375-1] 17144 DEBUG: autovacuum: processing database "blueface-crm"
Jun 28 08:03:01 bfiedb01 postgres[17166]: [ID 748848 local0.debug]
[45375-1] 17166 DEBUG: autovacuum: processing database "blueface-crm"
Jun 28 08:03:41 bfiedb01 postgres[29224]: [ID 748848 local0.debug]
[5392-1] 29224 DEBUG: checkpoint starting
Jun 28 08:03:41 bfiedb01 postgres[29224]: [ID 748848 local0.debug]
[5393-1] 29224 DEBUG: recycled transaction log file
"000000010000028800000072"
Jun 28 08:03:41 bfiedb01 postgres[29224]: [ID 748848 local0.debug]
[5394-1] 29224 DEBUG: checkpoint complete; 0 transaction log file(s)
added, 0 removed, 1 recycled
Jun 28 08:04:01 bfiedb01 postgres[17188]: [ID 748848 local0.debug]
[45375-1] 17188 DEBUG: autovacuum: processing database "blueface-crm"
Jun 28 08:05:01 bfiedb01 postgres[29121]: [ID 748848 local0.debug]
[45375-1] 29121 DEBUG: forked new backend, pid=17216 socket=9
Jun 28 08:05:01 bfiedb01 postgres[17217]: [ID 748848 local0.debug]
[45376-1] 17217 DEBUG: autovacuum: processing database "blueface-crm"
Jun 28 08:05:01 bfiedb01 postgres[29121]: [ID 748848 local0.debug]
[45376-1] 29121 DEBUG: server process (PID 17216) exited with exit
code 0
Jun 28 08:05:01 bfiedb01 postgres[29121]: [ID 748848 local0.debug]
[45377-1] 29121 DEBUG: forked new backend, pid=17218 socket=9
Jun 28 08:05:01 bfiedb01 postgres[29121]: [ID 748848 local0.debug]
[45378-1] 29121 DEBUG: server process (PID 17218) exited with exit
code 0
Jun 28 08:06:01 bfiedb01 postgres[17240]: [ID 748848 local0.debug]
[45379-1] 17240 DEBUG: autovacuum: processing database "blueface-crm"
Jun 28 08:07:01 bfiedb01 postgres[17262]: [ID 748848 local0.debug]
[45379-1] 17262 DEBUG: autovacuum: processing database "blueface-crm"
Jun 28 08:08:01 bfiedb01 postgres[17286]: [ID 748848 local0.debug]
[45379-1] 17286 DEBUG: autovacuum: processing database "blueface-crm"
Jun 28 08:08:41 bfiedb01 postgres[29224]: [ID 748848 local0.debug]
[5395-1] 29224 DEBUG: checkpoint starting
Jun 28 08:08:41 bfiedb01 postgres[29224]: [ID 748848 local0.debug]
[5396-1] 29224 DEBUG: checkpoint complete; 0 transaction log file(s)
added, 0 removed, 0 recycled
Jun 28 08:09:01 bfiedb01 postgres[17308]: [ID 748848 local0.debug]
[45379-1] 17308 DEBUG: autovacuum: processing database "blueface-crm"
Jun 28 08:10:01 bfiedb01 postgres[29121]: [ID 748848 local0.debug]
[45379-1] 29121 DEBUG: forked new backend, pid=17337 socket=9
Jun 28 08:10:01 bfiedb01 postgres[17338]: [ID 748848 local0.debug]
[45380-1] 17338 DEBUG: autovacuum: processing database "blueface-crm"
Jun 28 08:10:01 bfiedb01 postgres[29121]: [ID 748848 local0.debug]
[45380-1] 29121 DEBUG: server process (PID 17337) exited with exit
code 0
Jun 28 08:10:01 bfiedb01 postgres[29121]: [ID 748848 local0.debug]
[45381-1] 29121 DEBUG: forked new backend, pid=17339 socket=9
Jun 28 08:10:01 bfiedb01 postgres[29121]: [ID 748848 local0.debug]
[45382-1] 29121 DEBUG: server process (PID 17339) exited with exit
code 0
Jun 28 08:11:01 bfiedb01 postgres[17362]: [ID 748848 local0.debug]
[45383-1] 17362 DEBUG: autovacuum: processing database "blueface-crm"
Jun 28 08:11:11 bfiedb01 postgres[29121]: [ID 748848 local0.debug]
[45383-1] 29121 DEBUG: server process (PID 16521) exited with exit
code 0