Improve logging of autovacuum I/O activity

This adds some I/O stats to the logging of autovacuum (when the
operation takes long enough that log_autovacuum_min_duration causes it
to be logged), so that it is easier to tune.  Notably, it adds buffer
I/O counts (hits, misses, dirtied) and read and write rate.

Authors: Greg Smith and Noah Misch

diff --git a/src/backend/commands/vacuum.c b/src/backend/commands/vacuum.c
index 89e190df9569e5322505c487eb04ac9bbebc241f..5eec56950cc400669523145dbeecadfd5db5ce80 100644 (file)
--- a/src/backend/commands/vacuum.c
+++ b/src/backend/commands/vacuum.c
@@ -214,6 +214,9 @@ vacuum(VacuumStmt *vacstmt, Oid relid, bool do_toast,
 
                VacuumCostActive = (VacuumCostDelay > 0);
                VacuumCostBalance = 0;
+               VacuumPageHit = 0;
+               VacuumPageMiss = 0;
+               VacuumPageDirty = 0;
 
                /*
                 * Loop to process each selected relation.

diff --git a/src/backend/commands/vacuumlazy.c b/src/backend/commands/vacuumlazy.c
index 38deddc47c0d0c9bd8c3e17b7f39ac51d62dec7f..35472c50c1d7692ef9e91368eba6549525602f9f 100644 (file)
--- a/src/backend/commands/vacuumlazy.c
+++ b/src/backend/commands/vacuumlazy.c
@@ -155,6 +155,10 @@ lazy_vacuum_rel(Relation onerel, VacuumStmt *vacstmt,
        BlockNumber possibly_freeable;
        PGRUsage        ru0;
        TimestampTz starttime = 0;
+       long            secs;
+       int                     usecs;
+       double          read_rate,
+                               write_rate;
        bool            scan_all;
        TransactionId freezeTableLimit;
        BlockNumber new_rel_pages;
@@ -166,8 +170,7 @@ lazy_vacuum_rel(Relation onerel, VacuumStmt *vacstmt,
        if (IsAutoVacuumWorkerProcess() && Log_autovacuum_min_duration >= 0)
        {
                pg_rusage_init(&ru0);
-               if (Log_autovacuum_min_duration > 0)
-                       starttime = GetCurrentTimestamp();
+               starttime = GetCurrentTimestamp();
        }
 
        if (vacstmt->options & VACOPT_VERBOSE)
@@ -262,13 +265,29 @@ lazy_vacuum_rel(Relation onerel, VacuumStmt *vacstmt,
        /* and log the action if appropriate */
        if (IsAutoVacuumWorkerProcess() && Log_autovacuum_min_duration >= 0)
        {
+               TimestampTz     endtime = GetCurrentTimestamp();
+
                if (Log_autovacuum_min_duration == 0 ||
-                       TimestampDifferenceExceeds(starttime, GetCurrentTimestamp(),
+                       TimestampDifferenceExceeds(starttime, endtime,
                                                                           Log_autovacuum_min_duration))
+               {
+                       TimestampDifference(starttime, endtime, &secs, &usecs);
+
+                       read_rate = 0;
+                       write_rate = 0;
+                       if ((secs > 0) || (usecs > 0))
+                       {
+                               read_rate = (double) BLCKSZ * VacuumPageMiss / (1024 * 1024) /
+                                       (secs + usecs / 1000000.0);
+                               write_rate = (double) BLCKSZ * VacuumPageDirty / (1024 * 1024) /
+                                       (secs + usecs / 1000000.0);
+                       }
                        ereport(LOG,
                                        (errmsg("automatic vacuum of table \"%s.%s.%s\": index scans: %d\n"
                                                        "pages: %d removed, %d remain\n"
                                                        "tuples: %.0f removed, %.0f remain\n"
+                                                       "buffer usage: %d hits, %d misses, %d dirtied\n"
+                                                       "avg read rate: %.3f MiB/s, avg write rate: %.3f MiB/s\n"
                                                        "system usage: %s",
                                                        get_database_name(MyDatabaseId),
                                                        get_namespace_name(RelationGetNamespace(onerel)),
@@ -277,8 +296,13 @@ lazy_vacuum_rel(Relation onerel, VacuumStmt *vacstmt,
                                                        vacrelstats->pages_removed,
                                                        vacrelstats->rel_pages,
                                                        vacrelstats->tuples_deleted,
-                                                       new_rel_tuples,
+                                                       vacrelstats->new_rel_tuples,
+                                                       VacuumPageHit,
+                                                       VacuumPageMiss,
+                                                       VacuumPageDirty,
+                                                       read_rate,write_rate,
                                                        pg_rusage_show(&ru0))));
+               }
        }
 }
 

diff --git a/src/backend/storage/buffer/bufmgr.c b/src/backend/storage/buffer/bufmgr.c
index 2342506d679239bcef345c3aedca0fa1f61c3676..71fe8c665ecd4511d5b03dda7f70e5aea7ae5703 100644 (file)
--- a/src/backend/storage/buffer/bufmgr.c
+++ b/src/backend/storage/buffer/bufmgr.c
@@ -340,6 +340,7 @@ ReadBuffer_common(SMgrRelation smgr, char relpersistence, ForkNumber forkNum,
                {
                        /* Just need to update stats before we exit */
                        *hit = true;
+                       VacuumPageHit++;
 
                        if (VacuumCostActive)
                                VacuumCostBalance += VacuumCostPageHit;
@@ -471,6 +472,7 @@ ReadBuffer_common(SMgrRelation smgr, char relpersistence, ForkNumber forkNum,
                TerminateBufferIO(bufHdr, false, BM_VALID);
        }
 
+       VacuumPageMiss++;
        if (VacuumCostActive)
                VacuumCostBalance += VacuumCostPageMiss;
 
@@ -972,10 +974,14 @@ MarkBufferDirty(Buffer buffer)
        Assert(bufHdr->refcount > 0);
 
        /*
-        * If the buffer was not dirty already, do vacuum cost accounting.
+        * If the buffer was not dirty already, do vacuum accounting.
         */
-       if (!(bufHdr->flags & BM_DIRTY) && VacuumCostActive)
-               VacuumCostBalance += VacuumCostPageDirty;
+       if (!(bufHdr->flags & BM_DIRTY))
+       {
+               VacuumPageDirty++;
+               if (VacuumCostActive)
+                       VacuumCostBalance += VacuumCostPageDirty;
+       }
 
        bufHdr->flags |= (BM_DIRTY | BM_JUST_DIRTIED);
 
@@ -2337,8 +2343,12 @@ SetBufferCommitInfoNeedsSave(Buffer buffer)
        {
                LockBufHdr(bufHdr);
                Assert(bufHdr->refcount > 0);
-               if (!(bufHdr->flags & BM_DIRTY) && VacuumCostActive)
-                       VacuumCostBalance += VacuumCostPageDirty;
+               if (!(bufHdr->flags & BM_DIRTY))
+               {
+                       VacuumPageDirty++;
+                       if (VacuumCostActive)
+                               VacuumCostBalance += VacuumCostPageDirty;
+               }
                bufHdr->flags |= (BM_DIRTY | BM_JUST_DIRTIED);
                UnlockBufHdr(bufHdr);
        }

diff --git a/src/backend/utils/init/globals.c b/src/backend/utils/init/globals.c
index c4c41544a2126a9a7be8aed5d1dc27515af6e978..9ce64e67629bc7c9c776b141566a9700c97f11e6 100644 (file)
--- a/src/backend/utils/init/globals.c
+++ b/src/backend/utils/init/globals.c
@@ -115,6 +115,10 @@ int                        VacuumCostPageDirty = 20;
 int                    VacuumCostLimit = 200;
 int                    VacuumCostDelay = 0;
 
+int                    VacuumPageHit = 0;
+int                    VacuumPageMiss = 0;
+int                    VacuumPageDirty = 0;
+
 int                    VacuumCostBalance = 0;          /* working state for vacuum */
 bool           VacuumCostActive = false;
 

diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h
index 9d194171a564bf9be8786a4649f64bc3aa6810a4..4ee08fead6fea61c0fde3a7710d807ea16831d40 100644 (file)
--- a/src/include/miscadmin.h
+++ b/src/include/miscadmin.h
@@ -230,6 +230,10 @@ extern int VacuumCostPageDirty;
 extern int     VacuumCostLimit;
 extern int     VacuumCostDelay;
 
+extern int     VacuumPageHit;
+extern int     VacuumPageMiss;
+extern int     VacuumPageDirty;
+
 extern int     VacuumCostBalance;
 extern bool VacuumCostActive;