Re: Table-level log_autovacuum_min_duration

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);
ALTER TABLE t1 ALTER COLUMN name SET STORAGE EXTERNAL;
INSERT INTO t1 SELECT GENERATE_SERIES(1,100),repeat('a',3000);
UPDATE t1 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 100 row versions in 2 pages
### VERBOSE ###DETAIL: 33 index row versions were removed.
### VERBOSE ### 0 index pages have 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: 0 dead 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.00u sec 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 sec elapsed 0.00 sec
### VERBOSE ###INFO: analyzing "public.t1"
### VERBOSE ###INFO: "t1": scanned 2 of 2 pages, containing 100 live rows and 0 dead rows; 100 rows in sample, 100 estimated total rows
### LOG_AVAC ###LOG: automatic analyze of 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 versions in 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.00u sec elapsed 0.00 sec.
### VERBOSE ###INFO: "pg_toast_72882": found 200 removable, 0 nonremovable row versions in 50 out of 50 pages
### VERBOSE ###DETAIL: 0 dead 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.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