Re: Table-level log_autovacuum_min_duration - Mailing list pgsql-hackers

Hi, Michael

I found that definition of VERBOSE and log_autovacuum is not
pretty match. For example, "VERBOSE" can output logs of
scanning indices and scanning detail of analyze, but
log_autovacuum can't output them.

Please see following sequences.

1. execute these queries.
DROP TABLE t1;CREATE TABLE t1(id integer primary key,name text);ALTER TABLE t1 SET
(log_autovacuum_min_duration=0);ALTERTABLE t1 ALTER COLUMN name SET STORAGE EXTERNAL;INSERT INTO t1 SELECT
GENERATE_SERIES(1,100),repeat('a',3000);UPDATEt1 SET name='update'; 

2. after a while, output the following logs by autovacuum movement.
(For your convenience, I put the "### TYPE ###" prefix on each logs.)
### VERBOSE  ###INFO:  vacuuming "public.t1"### VERBOSE  ###INFO:  scanned index "t1_pkey" to remove 33 row versions###
VERBOSE ###DETAIL:  CPU 0.00s/0.00u sec elapsed 0.00 sec.### VERBOSE  ###INFO:  "t1": removed 33 row versions in 1
pages###VERBOSE  ###DETAIL:  CPU 0.00s/0.00u sec elapsed 0.00 sec.### VERBOSE  ###INFO:  index "t1_pkey" now contains
100row versions in 2 pages### VERBOSE  ###DETAIL:  33 index row versions were removed.### VERBOSE  ###        0 index
pageshave been deleted, 0 are currently reusable.### VERBOSE  ###        CPU 0.00s/0.00u sec elapsed 0.00 sec.###
VERBOSE ###INFO:  "t1": found 100 removable, 100 nonremovable row versions in 2 out of 2 pages### VERBOSE  ###DETAIL:
0dead row versions cannot be removed yet.### VERBOSE  ###        There were 0 unused item pointers.### VERBOSE  ###
  Skipped 0 pages due to buffer pins.### VERBOSE  ###        0 pages are entirely empty.### VERBOSE  ###        CPU
0.00s/0.00usec elapsed 0.00 sec.### LOG_AVAC ###LOG:  automatic vacuum of table "naoya.public.t1": index scans: 1###
LOG_AVAC###        pages: 0 removed, 2 remain, 0 skipped due to pins### LOG_AVAC ###        tuples: 100 removed, 100
remain,0 are dead but not yet removable### LOG_AVAC ###        buffer usage: 47 hits, 4 misses, 4 dirtied### LOG_AVAC
###       avg read rate: 14.192 MB/s, avg write rate: 14.192 MB/s### LOG_AVAC ###        system usage: CPU 0.00s/0.00u
secelapsed 0.00 sec### VERBOSE  ###INFO:  analyzing "public.t1"### VERBOSE  ###INFO:  "t1": scanned 2 of 2 pages,
containing100 live rows and 0 dead rows; 100 rows in sample, 100 estimated total rows### LOG_AVAC ###LOG:  automatic
analyzeof table "naoya.public.t1" system usage: CPU 0.00s/0.00u sec elapsed 0.04 sec### VERBOSE  ###INFO:  vacuuming
"pg_toast.pg_toast_72882"###VERBOSE  ###INFO:  scanned index "pg_toast_72882_index" to remove 200 row versions###
VERBOSE ###DETAIL:  CPU 0.00s/0.00u sec elapsed 0.00 sec.### VERBOSE  ###INFO:  "pg_toast_72882": removed 200 row
versionsin 50 pages### VERBOSE  ###DETAIL:  CPU 0.00s/0.00u sec elapsed 0.00 sec.### VERBOSE  ###INFO:  index
"pg_toast_72882_index"now contains 0 row versions in 2 pages### VERBOSE  ###DETAIL:  200 index row versions were
removed.###VERBOSE  ###        0 index pages have been deleted, 0 are currently reusable.### VERBOSE  ###        CPU
0.00s/0.00usec elapsed 0.00 sec.### VERBOSE  ###INFO:  "pg_toast_72882": found 200 removable, 0 nonremovable row
versionsin 50 out of 50 pages### VERBOSE  ###DETAIL:  0 dead row versions cannot be removed yet.### VERBOSE  ###
Therewere 0 unused item pointers.### VERBOSE  ###        Skipped 0 pages due to buffer pins.### VERBOSE  ###        0
pagesare entirely empty.### VERBOSE  ###        CPU 0.00s/0.00u sec elapsed 0.00 sec.### VERBOSE  ###INFO:
"pg_toast_72882":truncated 50 to 0 pages### VERBOSE  ###DETAIL:  CPU 0.00s/0.00u sec elapsed 0.03 sec.### LOG_AVAC
###LOG: automatic vacuum of table "naoya.pg_toast.pg_toast_72882": index scans: 1### LOG_AVAC ###        pages: 50
removed,0 remain, 0 skipped due to pins### LOG_AVAC ###        tuples: 200 removed, 0 remain, 0 are dead but not yet
removable###LOG_AVAC ###        buffer usage: 223 hits, 2 misses, 1 dirtied### LOG_AVAC ###        avg read rate: 0.457
MB/s,avg write rate: 0.228 MB/s### LOG_AVAC ###       system usage: CPU 0.00s/0.00u sec elapsed 0.03 sec 

I think VACOPT_VERBOSE should not be easily replaced to log_min_duration>=0.

And, in this v7 patch looks that VERBOSE log is always output
in INFO-Level when log_autovacuum_min_duration is set to 0.
Is this your point?

Regards,
---
Naoya