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;