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.

Author: alvherre

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"

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