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


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Reply via email to