Have VACUUM log number of skipped pages due to pins

Author: Jim Nasby, some kibitzing by Heikki Linnankangas.
Discussion leading to current behavior and precise wording fueled by
thoughts from Robert Haas and Andres Freund.

diff --git a/doc/src/sgml/ref/vacuum.sgml b/doc/src/sgml/ref/vacuum.sgml
index 450c94fcd3eab2096488a0d452e3d0b2c9b9e47e..19fd748dde0b523be578405479a2c23384f6b1f3 100644 (file)
--- a/doc/src/sgml/ref/vacuum.sgml
+++ b/doc/src/sgml/ref/vacuum.sgml
@@ -252,6 +252,7 @@ DETAIL:  CPU 0.01s/0.06u sec elapsed 0.07 sec.
 INFO:  "onek": found 3000 removable, 1000 nonremovable tuples in 143 pages
 DETAIL:  0 dead tuples cannot be removed yet.
 There were 0 unused item pointers.
+Skipped 0 pages due to buffer pins.
 0 pages are entirely empty.
 CPU 0.07s/0.39u sec elapsed 1.56 sec.
 INFO:  analyzing "public.onek"

diff --git a/src/backend/commands/vacuumlazy.c b/src/backend/commands/vacuumlazy.c
index 6db6c5cf47248ddd516dc9b622fb6e5ce6f4fb1a..3e68f951e290ff37fe9d4b63bf5cb6fb3b66a59d 100644 (file)
--- a/src/backend/commands/vacuumlazy.c
+++ b/src/backend/commands/vacuumlazy.c
@@ -105,6 +105,7 @@ typedef struct LVRelStats
    BlockNumber old_rel_pages;  /* previous value of pg_class.relpages */
    BlockNumber rel_pages;      /* total number of pages */
    BlockNumber scanned_pages;  /* number of pages we examined */
+   BlockNumber pinned_pages;   /* # of pages we could not initially lock */
    double      scanned_tuples; /* counts only tuples on scanned pages */
    double      old_rel_tuples; /* previous value of pg_class.reltuples */
    double      new_rel_tuples; /* new estimated total # of tuples */
@@ -332,6 +333,7 @@ lazy_vacuum_rel(Relation onerel, VacuumStmt *vacstmt,
            TimestampDifferenceExceeds(starttime, endtime,
                                       Log_autovacuum_min_duration))
        {
+           StringInfoData  buf;
            TimestampDifference(starttime, endtime, &secs, &usecs);
 
            read_rate = 0;
@@ -343,27 +345,47 @@ lazy_vacuum_rel(Relation onerel, VacuumStmt *vacstmt,
                write_rate = (double) BLCKSZ *VacuumPageDirty / (1024 * 1024) /
                            (secs + usecs / 1000000.0);
            }
+
+           /*
+            * This is pretty messy, but we split it up so that we can skip
+            * emitting individual parts of the message when not applicable.
+            */
+           initStringInfo(&buf);
+           appendStringInfo(&buf, _("automatic vacuum of table \"%s.%s.%s\": index scans: %d\n"),
+                            get_database_name(MyDatabaseId),
+                            get_namespace_name(RelationGetNamespace(onerel)),
+                            RelationGetRelationName(onerel),
+                            vacrelstats->num_index_scans);
+           appendStringInfo(&buf, _("pages: %d removed, %d remain\n"),
+                            vacrelstats->pages_removed,
+                            vacrelstats->rel_pages);
+           if (vacrelstats->pinned_pages > 0)
+           {
+               if (scan_all)
+                   appendStringInfo(&buf, _("waited for %d buffer pins\n"),
+                                    vacrelstats->pinned_pages);
+               else
+                   appendStringInfo(&buf,
+                                    _("skipped %d pages due to buffer pins\n"),
+                                    vacrelstats->pinned_pages);
+           }
+           appendStringInfo(&buf,
+                            _("tuples: %.0f removed, %.0f remain, %.0f are dead but not yet removable\n"),
+                            vacrelstats->tuples_deleted,
+                            vacrelstats->new_rel_tuples,
+                            vacrelstats->new_dead_tuples);
+           appendStringInfo(&buf,
+                            _("buffer usage: %d hits, %d misses, %d dirtied\n"),
+                            VacuumPageHit,
+                            VacuumPageMiss,
+                            VacuumPageDirty);
+           appendStringInfo(&buf, _("avg read rate: %.3f MB/s, avg write rate: %.3f MB/s\n"),
+                            read_rate, write_rate);
+           appendStringInfo(&buf, _("system usage: %s"), pg_rusage_show(&ru0));
+
            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, %.0f are dead but not yet removable\n"
-                           "buffer usage: %d hits, %d misses, %d dirtied\n"
-                     "avg read rate: %.3f MB/s, avg write rate: %.3f MB/s\n"
-                           "system usage: %s",
-                           get_database_name(MyDatabaseId),
-                           get_namespace_name(RelationGetNamespace(onerel)),
-                           RelationGetRelationName(onerel),
-                           vacrelstats->num_index_scans,
-                           vacrelstats->pages_removed,
-                           vacrelstats->rel_pages,
-                           vacrelstats->tuples_deleted,
-                           vacrelstats->new_rel_tuples,
-                           vacrelstats->new_dead_tuples,
-                           VacuumPageHit,
-                           VacuumPageMiss,
-                           VacuumPageDirty,
-                           read_rate, write_rate,
-                           pg_rusage_show(&ru0))));
+                   (errmsg_internal("%s", buf.data)));
+           pfree(buf.data);
        }
    }
 }
@@ -438,6 +460,7 @@ lazy_scan_heap(Relation onerel, LVRelStats *vacrelstats,
    BlockNumber next_not_all_visible_block;
    bool        skipping_all_visible_blocks;
    xl_heap_freeze_tuple *frozen;
+   StringInfoData  buf;
 
    pg_rusage_init(&ru0);
 
@@ -611,6 +634,8 @@ lazy_scan_heap(Relation onerel, LVRelStats *vacrelstats,
        /* We need buffer cleanup lock so that we can prune HOT chains. */
        if (!ConditionalLockBufferForCleanup(buf))
        {
+           vacrelstats->pinned_pages++;
+
            /*
             * If we're not scanning the whole relation to guard against XID
             * wraparound, it's OK to skip vacuuming a page.  The next vacuum
@@ -1094,19 +1119,37 @@ lazy_scan_heap(Relation onerel, LVRelStats *vacrelstats,
                        RelationGetRelationName(onerel),
                        tups_vacuumed, vacuumed_pages)));
 
+   /*
+    * This is pretty messy, but we split it up so that we can skip emitting
+    * individual parts of the message when not applicable.
+    */
+   initStringInfo(&buf);
+   appendStringInfo(&buf,
+                    _("%.0f dead row versions cannot be removed yet.\n"),
+                    nkeep);
+   appendStringInfo(&buf, _("There were %.0f unused item pointers.\n"),
+                    nunused);
+   if (vacrelstats->pinned_pages > 0)
+   {
+       if (scan_all)
+           appendStringInfo(&buf, _("Waited for %d buffer pins.\n"),
+                            vacrelstats->pinned_pages);
+       else
+           appendStringInfo(&buf, _("Skipped %u pages due to buffer pins.\n"),
+                            vacrelstats->pinned_pages);
+   }
+   appendStringInfo(&buf, _("%u pages are entirely empty.\n"),
+                    empty_pages);
+   appendStringInfo(&buf, _("%s."),
+                    pg_rusage_show(&ru0));
+
    ereport(elevel,
            (errmsg("\"%s\": found %.0f removable, %.0f nonremovable row versions in %u out of %u pages",
                    RelationGetRelationName(onerel),
                    tups_vacuumed, num_tuples,
                    vacrelstats->scanned_pages, nblocks),
-            errdetail("%.0f dead row versions cannot be removed yet.\n"
-                      "There were %.0f unused item pointers.\n"
-                      "%u pages are entirely empty.\n"
-                      "%s.",
-                      nkeep,
-                      nunused,
-                      empty_pages,
-                      pg_rusage_show(&ru0))));
+            errdetail_internal("%s", buf.data)));
+   pfree(buf.data);
 }