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);
 }