Track index and database vacuum time and cost-based delay

Add cumulative elapsed and delay time for indexes and databases, and
delay time for tables. Keep manual VACUUM and autovacuum totals separate.
Database totals use table timings, which already include index work.

Adapt v44-0002 to Cloudberry's PostgreSQL 14 UDP collector, including AO
vacuum. Store times in microseconds and report delay in VACUUM VERBOSE
and autovacuum logs. Collection follows track_counts; delay measurement
also requires track_cost_delay_timing and excludes ANALYZE calls.

SQL access is provided separately through vacuum_stats. Bump the
statistics-file format for the new fields; the system catalog is unchanged.

Based-on: https://www.postgresql.org/message-id/attachment/204703/v44-0002-Track-vacuum-times-for-indexes-and-databases-and.patch
(cherry picked from commit 77a3ffa32d07d8a2947bf7e8dbb8d342ce05549d)

Co-authored-by: Andrei Lepikhov <lepihov@gmail.com>
Co-authored-by: Andrei Zubkov <zubkov@moonset.ru>

Author: 3 people

src/backend/access/heap/vacuumlazy.c

@@ -517,6 +517,9 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
 	bool		aggressive;		/* should we scan all unfrozen pages? */
 	bool		scanned_all_unfrozen;	/* actually scanned all such pages? */
 	bool		freeze_age_vacuum; /* aggressive due to freeze age? */
+	instr_time	vacstart;
+	int64		startdelaytime;
+	instr_time	vacend;
 	char	  **indnames = NULL;
 	TransactionId xidFullScanLimit;
 	MultiXactId mxactFullScanLimit;
@@ -535,6 +538,10 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
 	/* Used for instrumentation and cumulative maintenance statistics. */
 	starttime = GetCurrentTimestamp();
 
+	/* measure elapsed and delay time for the vacuum statistics */
+	INSTR_TIME_SET_CURRENT(vacstart);
+	startdelaytime = VacuumDelayTime;
+
 	/* measure elapsed time iff autovacuum logging requires it */
 	if (IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0)
 	{
@@ -767,11 +774,13 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
 	pgstat_report_vacuum(RelationGetRelid(rel),
 						 rel->rd_rel->relisshared,
 						 Max(new_live_tuples, 0),
-						 vacrel->new_dead_tuples, starttime);
+						 vacrel->new_dead_tuples, starttime,
+						 VacuumDelayTime - startdelaytime);
 
 	/* assemble the per-vacuum measurements for subsequent reporting */
 	{
 		PgStat_VacuumStats vacstats;
+		PgStat_Counter elapsedtime;
 
 		MemSet(&vacstats, 0, sizeof(vacstats));
 		vacstats.tuples_deleted = (PgStat_Counter) vacrel->tuples_deleted;
@@ -782,9 +791,16 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
 		vacstats.pages_all_visible = (PgStat_Counter) vacrel->pages_all_visible;
 		vacstats.freeze_age_vacuum_count = freeze_age_vacuum ? 1 : 0;
 
+		INSTR_TIME_SET_CURRENT(vacend);
+		INSTR_TIME_SUBTRACT(vacend, vacstart);
+		elapsedtime = (PgStat_Counter) INSTR_TIME_GET_MICROSEC(vacend);
+
 		ereport(elevel,
 				(errmsg("table \"%s\": vacuum statistics", vacrel->relname),
-				 errdetail("aggressive scan required by freeze age: %s",
+				 errdetail("elapsed: %.3f ms, cost-based delay: %.3f ms\n"
+						   "aggressive scan required by freeze age: %s",
+						   elapsedtime / 1000.0,
+						   (VacuumDelayTime - startdelaytime) / 1000.0,
 						   freeze_age_vacuum ? _("yes") : _("no"))));
 
 	}
@@ -930,6 +946,8 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
 							 (long long) walusage.wal_records,
 							 (long long) walusage.wal_fpi,
 							 (unsigned long long) walusage.wal_bytes);
+			appendStringInfo(&buf, _("cost-based delay: %.3f ms\n"),
+							 (VacuumDelayTime - startdelaytime) / 1000.0);
 			appendStringInfo(&buf, _("system usage: %s"), pg_rusage_show(&ru0));
 
 			ereport(LOG,
@@ -3117,7 +3135,8 @@ lazy_cleanup_all_indexes(LVRelState *vacrel)
  * is skipped, and keeps it from being counted twice when it is not.
  */
 static IndexBulkDeleteResult
-lazy_index_vacstats_start(IndexBulkDeleteResult *istat)
+lazy_index_vacstats_start(IndexBulkDeleteResult *istat,
+						  instr_time *starttime, int64 *startdelaytime)
 {
 	IndexBulkDeleteResult before;
 
@@ -3126,6 +3145,9 @@ lazy_index_vacstats_start(IndexBulkDeleteResult *istat)
 	else
 		MemSet(&before, 0, sizeof(before));
 
+	INSTR_TIME_SET_CURRENT(*starttime);
+	*startdelaytime = VacuumDelayTime;
+
 	return before;
 }
 
@@ -3139,9 +3161,14 @@ lazy_index_vacstats_start(IndexBulkDeleteResult *istat)
  */
 static void
 lazy_index_vacstats_finish(Relation indrel, IndexBulkDeleteResult *istat,
-						   IndexBulkDeleteResult *before, bool cleanup)
+						   IndexBulkDeleteResult *before, bool cleanup,
+						   instr_time starttime, int64 startdelaytime)
 {
 	PgStat_VacuumStats vacstats;
+	instr_time	endtime;
+
+	INSTR_TIME_SET_CURRENT(endtime);
+	INSTR_TIME_SUBTRACT(endtime, starttime);
 
 	MemSet(&vacstats, 0, sizeof(vacstats));
 	if (istat)
@@ -3162,6 +3189,11 @@ lazy_index_vacstats_finish(Relation indrel, IndexBulkDeleteResult *istat,
 				(PgStat_Counter) (istat->pages_deleted - istat->pages_free);
 	}
 
+	pgstat_report_index_vacuum_time(indrel,
+									   (PgStat_Counter) INSTR_TIME_GET_MICROSEC(endtime),
+									   VacuumDelayTime - startdelaytime,
+									   IsAutoVacuumWorkerProcess());
+
 }
 
 /*
@@ -3183,6 +3215,8 @@ lazy_vacuum_one_index(Relation indrel, IndexBulkDeleteResult *istat,
 	PGRUsage	ru0;
 	LVSavedErrInfo saved_err_info;
 	IndexBulkDeleteResult istat_before;
+	instr_time	starttime;
+	int64		startdelaytime;
 
 	pg_rusage_init(&ru0);
 
@@ -3207,15 +3241,19 @@ lazy_vacuum_one_index(Relation indrel, IndexBulkDeleteResult *istat,
 							 InvalidBlockNumber, InvalidOffsetNumber);
 
 	/* Do bulk deletion */
-	istat_before = lazy_index_vacstats_start(istat);
+	istat_before = lazy_index_vacstats_start(istat, &starttime,
+											 &startdelaytime);
 	istat = index_bulk_delete(&ivinfo, istat, lazy_tid_reaped,
 							  (void *) vacrel->dead_tuples);
-	lazy_index_vacstats_finish(indrel, istat, &istat_before, false);
+	lazy_index_vacstats_finish(indrel, istat, &istat_before, false,
+							   starttime, startdelaytime);
 
 	ereport(elevel,
 			(errmsg("scanned index \"%s\" to remove %d row versions",
 					vacrel->indname, vacrel->dead_tuples->num_tuples),
-			 errdetail_internal("%s", pg_rusage_show(&ru0))));
+			 errdetail("cost-based delay: %.3f ms\n%s",
+					   (VacuumDelayTime - startdelaytime) / 1000.0,
+					   pg_rusage_show(&ru0))));
 
 	/* Revert to the previous phase information for error traceback */
 	restore_vacuum_error_info(vacrel, &saved_err_info);
@@ -3242,6 +3280,8 @@ lazy_cleanup_one_index(Relation indrel, IndexBulkDeleteResult *istat,
 	PGRUsage	ru0;
 	LVSavedErrInfo saved_err_info;
 	IndexBulkDeleteResult istat_before;
+	instr_time	starttime;
+	int64		startdelaytime;
 
 	pg_rusage_init(&ru0);
 
@@ -3266,9 +3306,11 @@ lazy_cleanup_one_index(Relation indrel, IndexBulkDeleteResult *istat,
 							 VACUUM_ERRCB_PHASE_INDEX_CLEANUP,
 							 InvalidBlockNumber, InvalidOffsetNumber);
 
-	istat_before = lazy_index_vacstats_start(istat);
+	istat_before = lazy_index_vacstats_start(istat, &starttime,
+											 &startdelaytime);
 	istat = index_vacuum_cleanup(&ivinfo, istat);
-	lazy_index_vacstats_finish(indrel, istat, &istat_before, true);
+	lazy_index_vacstats_finish(indrel, istat, &istat_before, true,
+							   starttime, startdelaytime);
 
 	if (istat)
 	{
@@ -3280,10 +3322,12 @@ lazy_cleanup_one_index(Relation indrel, IndexBulkDeleteResult *istat,
 				 errdetail("%.0f index row versions were removed.\n"
 						   "%u index pages were newly deleted.\n"
 						   "%u index pages are currently deleted, of which %u are currently reusable.\n"
+						   "cost-based delay: %.3f ms\n"
 						   "%s.",
 						   (istat)->tuples_removed,
 						   (istat)->pages_newly_deleted,
 						   (istat)->pages_deleted, (istat)->pages_free,
+						   (VacuumDelayTime - startdelaytime) / 1000.0,
 						   pg_rusage_show(&ru0))));
 	}
 

src/backend/commands/vacuum_ao.c

@@ -322,7 +322,9 @@ ao_vacuum_rel_post_cleanup(Relation onerel, VacuumParams *params, BufferAccessSt
 						 onerel->rd_rel->relisshared,
 						 reltuples,
 						 deadtuples,
-						 vacrelstats->starttime);
+						 vacrelstats->starttime,
+						 vacrelstats->delay_time +
+						 (VacuumDelayTime - vacrelstats->phase_start_delay));
 
 	/*
 	 * Remember what is left behind for the vacuum statistics, which
@@ -491,6 +493,7 @@ ao_vacuum_rel(Relation rel, VacuumParams *params, BufferAccessStrategy bstrategy
 	 */
 	INSTR_TIME_SET_CURRENT(phasestart);
 	startdelaytime = VacuumDelayTime;
+	vacrelstats->phase_start_delay = startdelaytime;
 
 	if (ao_vacuum_phase == VACOPT_AO_PRE_CLEANUP_PHASE)
 		ao_vacuum_rel_pre_cleanup(rel, params, bstrategy, vacrelstats);

src/backend/postmaster/pgstat.c

@@ -1590,7 +1590,7 @@ pgstat_report_autovac(Oid dboid)
 void
 pgstat_report_vacuum(Oid tableoid, bool shared,
 					 PgStat_Counter livetuples, PgStat_Counter deadtuples,
-					 TimestampTz starttime)
+					 TimestampTz starttime, PgStat_Counter delaytime)
 {
 	PgStat_MsgVacuum msg;
 
@@ -1601,13 +1601,36 @@ pgstat_report_vacuum(Oid tableoid, bool shared,
 	msg.m_databaseid = shared ? InvalidOid : MyDatabaseId;
 	msg.m_tableoid = tableoid;
 	msg.m_autovacuum = IsAutoVacuumWorkerProcess();
+	msg.m_isindex = false;
+	msg.m_delaytime = delaytime;
 	msg.m_vacuumtime = GetCurrentTimestamp();
 	msg.m_elapsedtime = Max(msg.m_vacuumtime - starttime, 0);
 	msg.m_live_tuples = livetuples;
 	msg.m_dead_tuples = deadtuples;
 	pgstat_send(&msg, sizeof(msg));
 }
 
+/* Report an index pass without changing table estimates or vacuum counts. */
+void
+pgstat_report_index_vacuum_time(Relation rel, PgStat_Counter elapsedtime,
+								PgStat_Counter delaytime, bool is_autovacuum)
+{
+	PgStat_MsgVacuum msg;
+
+	if (pgStatSock == PGINVALID_SOCKET || !pgstat_track_counts)
+		return;
+
+	MemSet(&msg, 0, sizeof(msg));
+	pgstat_setheader(&msg.m_hdr, PGSTAT_MTYPE_VACUUM);
+	msg.m_databaseid = rel->rd_rel->relisshared ? InvalidOid : MyDatabaseId;
+	msg.m_tableoid = RelationGetRelid(rel);
+	msg.m_autovacuum = is_autovacuum;
+	msg.m_isindex = true;
+	msg.m_elapsedtime = elapsedtime;
+	msg.m_delaytime = delaytime;
+	pgstat_send(&msg, sizeof(msg));
+}
+
 /* --------
  * pgstat_report_analyze() -
  *
@@ -3823,9 +3846,14 @@ reset_dbentry_counters(PgStat_StatDBEntry *dbentry)
 	dbentry->n_sessions_abandoned = 0;
 	dbentry->n_sessions_fatal = 0;
 	dbentry->n_sessions_killed = 0;
+	dbentry->total_vacuum_time = 0;
+	dbentry->total_autovacuum_time = 0;
+	dbentry->total_vacuum_delay_time = 0;
+	dbentry->total_autovacuum_delay_time = 0;
 	dbentry->n_frozen_page_marks_cleared = 0;
 	dbentry->n_visible_page_marks_cleared = 0;
 
+
 	dbentry->stat_reset_timestamp = GetCurrentTimestamp();
 	dbentry->stats_timestamp = 0;
 
@@ -3919,12 +3947,14 @@ pgstat_get_tab_entry(PgStat_StatDBEntry *dbentry, Oid tableoid, bool create)
 		result->analyze_count = 0;
 		result->autovac_analyze_timestamp = 0;
 		result->autovac_analyze_count = 0;
-		result->frozen_page_marks_cleared = 0;
-		result->visible_page_marks_cleared = 0;
 		result->total_vacuum_time = 0;
 		result->total_autovacuum_time = 0;
 		result->total_analyze_time = 0;
 		result->total_autoanalyze_time = 0;
+		result->total_vacuum_delay_time = 0;
+		result->total_autovacuum_delay_time = 0;
+		result->frozen_page_marks_cleared = 0;
+		result->visible_page_marks_cleared = 0;
 	}
 
 	return result;
@@ -5286,12 +5316,14 @@ pgstat_recv_tabstat(PgStat_MsgTabstat *msg, int len)
 			tabentry->analyze_count = 0;
 			tabentry->autovac_analyze_timestamp = 0;
 			tabentry->autovac_analyze_count = 0;
-			tabentry->frozen_page_marks_cleared = 0;
-			tabentry->visible_page_marks_cleared = 0;
 			tabentry->total_vacuum_time = 0;
 			tabentry->total_autovacuum_time = 0;
 			tabentry->total_analyze_time = 0;
 			tabentry->total_autoanalyze_time = 0;
+			tabentry->total_vacuum_delay_time = 0;
+			tabentry->total_autovacuum_delay_time = 0;
+			tabentry->frozen_page_marks_cleared = 0;
+			tabentry->visible_page_marks_cleared = 0;
 		}
 		else
 		{
@@ -5630,6 +5662,32 @@ pgstat_recv_vacuum(PgStat_MsgVacuum *msg, int len)
 
 	tabentry = pgstat_get_tab_entry(dbentry, msg->m_tableoid, true);
 
+	if (msg->m_autovacuum)
+	{
+		tabentry->total_autovacuum_time += msg->m_elapsedtime;
+		tabentry->total_autovacuum_delay_time += msg->m_delaytime;
+	}
+	else
+	{
+		tabentry->total_vacuum_time += msg->m_elapsedtime;
+		tabentry->total_vacuum_delay_time += msg->m_delaytime;
+	}
+
+	/* Index passes are already included in the owning table's elapsed time. */
+	if (msg->m_isindex)
+		return;
+
+	if (msg->m_autovacuum)
+	{
+		dbentry->total_autovacuum_time += msg->m_elapsedtime;
+		dbentry->total_autovacuum_delay_time += msg->m_delaytime;
+	}
+	else
+	{
+		dbentry->total_vacuum_time += msg->m_elapsedtime;
+		dbentry->total_vacuum_delay_time += msg->m_delaytime;
+	}
+
 	tabentry->n_live_tuples = msg->m_live_tuples;
 	tabentry->n_dead_tuples = msg->m_dead_tuples;
 
@@ -5649,13 +5707,11 @@ pgstat_recv_vacuum(PgStat_MsgVacuum *msg, int len)
 	{
 		tabentry->autovac_vacuum_timestamp = msg->m_vacuumtime;
 		tabentry->autovac_vacuum_count++;
-		tabentry->total_autovacuum_time += msg->m_elapsedtime;
 	}
 	else
 	{
 		tabentry->vacuum_timestamp = msg->m_vacuumtime;
 		tabentry->vacuum_count++;
-		tabentry->total_vacuum_time += msg->m_elapsedtime;
 	}
 }
 

src/include/access/appendonly_compaction.h

@@ -36,6 +36,7 @@ typedef struct AOVacuumRelStats
 
 	/* for the vacuum statistics, accumulated over all the phases */
 	int64	vacuum_time;		/* time spent in the phases, in microseconds */
+	int64	phase_start_delay; /* counter at the start of the current phase */
 	int64	delay_time;			/* of which the cost-based vacuum delay */
 	int64	dead_tuples_left;	/* tuples the post-cleanup found still hidden */
 } AOVacuumRelStats;