From 77a3ffa32d07d8a2947bf7e8dbb8d342ce05549d Mon Sep 17 00:00:00 2001 From: Alena Rybakina Date: Mon, 20 Jul 2026 16:57:07 +0300 Subject: [PATCH v43 2/9] Track vacuum times for indexes and databases, and vacuum delay, in pg_stat views. Vacuum currently keeps cumulative time only per table (total_(auto)vacuum_time in pg_stat_all_tables), where the time spent in a bloated index is indistinguishable from heap time, and the sleep in cost-based delay points is visible only transiently in pg_stat_progress_vacuum and in the log line. Add: * pg_stat_all_indexes: total_vacuum_time, total_autovacuum_time, total_vacuum_delay_time, total_autovacuum_delay_time - accumulated per pass (a bulkdelete pass per index scan cycle plus a final cleanup pass, including passes in parallel workers; workers classify autovacuum via the leader's DSM flag); * pg_stat_all_tables: total_vacuum_delay_time, total_autovacuum_delay_time - covering the whole heap_vacuum_rel() run, matching the scope of total_vacuum_time; * pg_stat_database: total_vacuum_time, total_autovacuum_time, total_vacuum_delay_time, total_autovacuum_delay_time - the database-wide totals of the table runs (index processing happens inside the owning table's run and is not added again). Delay times advance only when track_cost_delay_timing is enabled, accumulated in the new VacuumDelayTime process counter. Authors: Alena Rybakina , Andrei Lepikhov , Andrei Zubkov --- doc/src/sgml/monitoring.sgml | 109 ++++++++++++++++++ src/backend/access/heap/vacuumlazy.c | 33 +++++- src/backend/catalog/system_views.sql | 10 ++ src/backend/commands/vacuum.c | 7 ++ src/backend/commands/vacuumparallel.c | 16 +++ src/backend/utils/activity/pgstat_database.c | 4 + src/backend/utils/activity/pgstat_index.c | 43 +++++++ src/backend/utils/activity/pgstat_relation.c | 26 ++++- src/backend/utils/adt/pgstatfuncs.c | 49 ++++++++ src/include/catalog/pg_proc.dat | 44 +++++++ src/include/commands/vacuum.h | 1 + src/include/pgstat.h | 41 ++++++- src/test/modules/test_misc/meson.build | 1 + .../test_misc/t/016_index_vacuum_time.pl | 72 ++++++++++++ src/test/regress/expected/rules.out | 22 ++++ 15 files changed, 475 insertions(+), 3 deletions(-) create mode 100644 src/test/modules/test_misc/t/016_index_vacuum_time.pl diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml index 62dadf3e86c..c83caeb3677 100644 --- a/doc/src/sgml/monitoring.sgml +++ b/doc/src/sgml/monitoring.sgml @@ -4230,6 +4230,49 @@ description | Waiting for a newly initialized WAL file to reach durable storage + + + total_vacuum_time double precision + + + Total time manually invoked vacuums spent processing tables of this + database, in milliseconds (index processing is included in the owning + table's run) + + + + + + total_autovacuum_time double precision + + + Total time the autovacuum daemon spent processing tables of this + database, in milliseconds + + + + + + total_vacuum_delay_time double precision + + + Total time manually invoked vacuums of this database spent sleeping in + cost-based delay points, in milliseconds (counted only when + is enabled) + + + + + + total_autovacuum_delay_time double precision + + + Total time autovacuums of this database spent sleeping in cost-based + delay points, in milliseconds (counted only when + is enabled) + + + session_time double precision @@ -4577,6 +4620,50 @@ description | Waiting for a newly initialized WAL file to reach durable storage + + + total_vacuum_time double precision + + + Total time this index has been processed by manually invoked vacuums, + in milliseconds. (This includes the time spent sleeping due to + cost-based delays.) + + + + + + total_autovacuum_time double precision + + + Total time this index has been processed by the autovacuum daemon, + in milliseconds. (This includes the time spent sleeping due to + cost-based delays.) + + + + + + total_vacuum_delay_time double precision + + + Total time manually invoked vacuums spent sleeping in cost-based delay + points while processing this index, in milliseconds (counted only when + is enabled) + + + + + + total_autovacuum_delay_time double precision + + + Total time the autovacuum daemon spent sleeping in cost-based delay + points while processing this index, in milliseconds (counted only when + is enabled) + + + n_tup_ins bigint @@ -4790,6 +4877,28 @@ description | Waiting for a newly initialized WAL file to reach durable storage + + + total_vacuum_delay_time double precision + + + Total time this table's vacuums spent sleeping in cost-based delay + points, in milliseconds (counted only when + is enabled) + + + + + + total_autovacuum_delay_time double precision + + + Total time autovacuums of this table spent sleeping in cost-based + delay points, in milliseconds (counted only when + is enabled) + + + stats_reset timestamp with time zone diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c index f43c6848146..2f0d839ee4b 100644 --- a/src/backend/access/heap/vacuumlazy.c +++ b/src/backend/access/heap/vacuumlazy.c @@ -129,6 +129,8 @@ */ #include "postgres.h" +#include + #include "access/genam.h" #include "access/heapam.h" #include "access/htup_details.h" @@ -638,6 +640,7 @@ heap_vacuum_rel(Relation rel, const VacuumParams *params, TimestampTz starttime = 0; PgStat_Counter startreadtime = 0, startwritetime = 0; + double startdelaytime; WalUsage startwalusage = pgWalUsage; BufferUsage startbufferusage = pgBufferUsage; ErrorContextCallback errcallback; @@ -659,6 +662,7 @@ heap_vacuum_rel(Relation rel, const VacuumParams *params, /* Used for instrumentation and stats report */ starttime = GetCurrentTimestamp(); + startdelaytime = VacuumDelayTime; pgstat_progress_start_command(PROGRESS_COMMAND_VACUUM, RelationGetRelid(rel)); @@ -984,11 +988,18 @@ heap_vacuum_rel(Relation rel, const VacuumParams *params, * soon in cases where the failsafe prevented significant amounts of heap * vacuuming. */ + /* + * The delay counter covers the whole heap_vacuum_rel() run, matching the + * scope of total_vacuum_time. In a parallel vacuum it covers the + * leader's sleeps only; parallel workers account their own sleeps to the + * indexes they process. + */ pgstat_report_vacuum(rel, Max(vacrel->new_live_tuples, 0), vacrel->recently_dead_tuples + vacrel->missed_dead_tuples, - starttime); + starttime, + (PgStat_Counter) rint(VacuumDelayTime - startdelaytime)); pgstat_progress_end_command(); if (instrument) @@ -3039,6 +3050,8 @@ lazy_vacuum_one_index(Relation indrel, IndexBulkDeleteResult *istat, { IndexVacuumInfo ivinfo; LVSavedErrInfo saved_err_info; + TimestampTz istarttime = GetCurrentTimestamp(); + double startdelaytime = VacuumDelayTime; ivinfo.index = indrel; ivinfo.heaprel = vacrel->rel; @@ -3065,6 +3078,14 @@ lazy_vacuum_one_index(Relation indrel, IndexBulkDeleteResult *istat, istat = vac_bulkdel_one_index(&ivinfo, istat, vacrel->dead_items, vacrel->dead_items_info); + /* Accumulate this pass into the index's cumulative vacuum times */ + pgstat_report_index_vacuum_time(indrel, + TimestampDifferenceMilliseconds(istarttime, + GetCurrentTimestamp()), + (PgStat_Counter) rint(VacuumDelayTime - + startdelaytime), + AmAutoVacuumWorkerProcess()); + /* Revert to the previous phase information for error traceback */ restore_vacuum_error_info(vacrel, &saved_err_info); pfree(vacrel->indname); @@ -3089,6 +3110,8 @@ lazy_cleanup_one_index(Relation indrel, IndexBulkDeleteResult *istat, { IndexVacuumInfo ivinfo; LVSavedErrInfo saved_err_info; + TimestampTz istarttime = GetCurrentTimestamp(); + double startdelaytime = VacuumDelayTime; ivinfo.index = indrel; ivinfo.heaprel = vacrel->rel; @@ -3114,6 +3137,14 @@ lazy_cleanup_one_index(Relation indrel, IndexBulkDeleteResult *istat, istat = vac_cleanup_one_index(&ivinfo, istat); + /* Accumulate this pass into the index's cumulative vacuum times */ + pgstat_report_index_vacuum_time(indrel, + TimestampDifferenceMilliseconds(istarttime, + GetCurrentTimestamp()), + (PgStat_Counter) rint(VacuumDelayTime - + startdelaytime), + AmAutoVacuumWorkerProcess()); + /* Revert to the previous phase information for error traceback */ restore_vacuum_error_info(vacrel, &saved_err_info); pfree(vacrel->indname); diff --git a/src/backend/catalog/system_views.sql b/src/backend/catalog/system_views.sql index ad340887f54..322241c8ea0 100644 --- a/src/backend/catalog/system_views.sql +++ b/src/backend/catalog/system_views.sql @@ -747,6 +747,8 @@ CREATE VIEW pg_stat_all_tables AS pg_stat_get_total_autovacuum_time(C.oid) AS total_autovacuum_time, pg_stat_get_total_analyze_time(C.oid) AS total_analyze_time, pg_stat_get_total_autoanalyze_time(C.oid) AS total_autoanalyze_time, + pg_stat_get_total_vacuum_delay_time(C.oid) AS total_vacuum_delay_time, + pg_stat_get_total_autovacuum_delay_time(C.oid) AS total_autovacuum_delay_time, pg_stat_get_stat_reset_time(C.oid) AS stats_reset FROM pg_class C LEFT JOIN pg_index I ON C.oid = I.indrelid @@ -869,6 +871,10 @@ CREATE VIEW pg_stat_all_indexes AS pg_stat_get_idx_lastscan(I.oid) AS last_idx_scan, pg_stat_get_idx_tuples_returned(I.oid) AS idx_tup_read, pg_stat_get_idx_tuples_fetched(I.oid) AS idx_tup_fetch, + pg_stat_get_idx_total_vacuum_time(I.oid) AS total_vacuum_time, + pg_stat_get_idx_total_autovacuum_time(I.oid) AS total_autovacuum_time, + pg_stat_get_idx_total_vacuum_delay_time(I.oid) AS total_vacuum_delay_time, + pg_stat_get_idx_total_autovacuum_delay_time(I.oid) AS total_autovacuum_delay_time, pg_stat_get_idx_stat_reset_time(I.oid) AS stats_reset FROM pg_class C JOIN pg_index X ON C.oid = X.indrelid JOIN @@ -1172,6 +1178,10 @@ CREATE VIEW pg_stat_database AS pg_stat_get_db_checksum_last_failure(D.oid) AS checksum_last_failure, pg_stat_get_db_blk_read_time(D.oid) AS blk_read_time, pg_stat_get_db_blk_write_time(D.oid) AS blk_write_time, + pg_stat_get_db_total_vacuum_time(D.oid) AS total_vacuum_time, + pg_stat_get_db_total_autovacuum_time(D.oid) AS total_autovacuum_time, + pg_stat_get_db_total_vacuum_delay_time(D.oid) AS total_vacuum_delay_time, + pg_stat_get_db_total_autovacuum_delay_time(D.oid) AS total_autovacuum_delay_time, pg_stat_get_db_session_time(D.oid) AS session_time, pg_stat_get_db_active_time(D.oid) AS active_time, pg_stat_get_db_idle_in_transaction_time(D.oid) AS idle_in_transaction_time, diff --git a/src/backend/commands/vacuum.c b/src/backend/commands/vacuum.c index d8c2f33c615..6939af5652f 100644 --- a/src/backend/commands/vacuum.c +++ b/src/backend/commands/vacuum.c @@ -96,6 +96,12 @@ int vacuum_cost_limit = 200; /* Variable for reporting cost-based vacuum delay from parallel workers. */ int64 parallel_vacuum_worker_delay_ns = 0; +/* + * Cumulative time this process has slept in cost-based vacuum delay points, + * in milliseconds. Only advances when track_cost_delay_timing is enabled. + */ +double VacuumDelayTime = 0; + /* * VacuumFailsafeActive is a defined as a global so that we can determine * whether or not to re-enable cost-based vacuum delay when vacuuming a table. @@ -2559,6 +2565,7 @@ vacuum_delay_point(bool is_analyze) INSTR_TIME_SET_CURRENT(delay_end); INSTR_TIME_SET_ZERO(delay); INSTR_TIME_ACCUM_DIFF(delay, delay_end, delay_start); + VacuumDelayTime += INSTR_TIME_GET_MILLISEC(delay); /* * For parallel workers, we only report the delay time every once diff --git a/src/backend/commands/vacuumparallel.c b/src/backend/commands/vacuumparallel.c index 767d162e578..a3c1ae3cc29 100644 --- a/src/backend/commands/vacuumparallel.c +++ b/src/backend/commands/vacuumparallel.c @@ -35,6 +35,8 @@ */ #include "postgres.h" +#include + #include "access/amapi.h" #include "access/table.h" #include "access/xact.h" @@ -1076,6 +1078,8 @@ parallel_vacuum_process_one_index(ParallelVacuumState *pvs, Relation indrel, IndexBulkDeleteResult *istat = NULL; IndexBulkDeleteResult *istat_res; IndexVacuumInfo ivinfo; + TimestampTz istarttime = GetCurrentTimestamp(); + double startdelaytime = VacuumDelayTime; /* * Update the pointer to the corresponding bulk-deletion result if someone @@ -1112,6 +1116,18 @@ parallel_vacuum_process_one_index(ParallelVacuumState *pvs, Relation indrel, RelationGetRelationName(indrel)); } + /* + * Accumulate this pass into the index's cumulative vacuum times. Use the + * leader's DSM flag to classify autovacuum: a parallel worker of an + * autovacuum leader is a regular background worker. + */ + pgstat_report_index_vacuum_time(indrel, + TimestampDifferenceMilliseconds(istarttime, + GetCurrentTimestamp()), + (PgStat_Counter) rint(VacuumDelayTime - + startdelaytime), + pvs->shared->is_autovacuum); + /* * Copy the index bulk-deletion result returned from ambulkdelete and * amvacuumcleanup to the DSM segment if it's the first cycle because they diff --git a/src/backend/utils/activity/pgstat_database.c b/src/backend/utils/activity/pgstat_database.c index 7f3bc016593..c906f16eb1b 100644 --- a/src/backend/utils/activity/pgstat_database.c +++ b/src/backend/utils/activity/pgstat_database.c @@ -480,6 +480,10 @@ pgstat_database_flush_cb(PgStat_EntryRef *entry_ref, bool nowait) PGSTAT_ACCUM_DBCOUNT(blk_read_time); PGSTAT_ACCUM_DBCOUNT(blk_write_time); + PGSTAT_ACCUM_DBCOUNT(total_vacuum_time); + PGSTAT_ACCUM_DBCOUNT(total_autovacuum_time); + PGSTAT_ACCUM_DBCOUNT(total_vacuum_delay_time); + PGSTAT_ACCUM_DBCOUNT(total_autovacuum_delay_time); PGSTAT_ACCUM_DBCOUNT(sessions); PGSTAT_ACCUM_DBCOUNT(session_time); diff --git a/src/backend/utils/activity/pgstat_index.c b/src/backend/utils/activity/pgstat_index.c index a1f9a4c6ac1..0747dbe7569 100644 --- a/src/backend/utils/activity/pgstat_index.c +++ b/src/backend/utils/activity/pgstat_index.c @@ -95,6 +95,49 @@ pgstat_index_delete_pending_cb(PgStat_EntryRef *entry_ref) pgstat_unlink_relation(pending->relation); } +/* + * Report the time spent vacuuming an index. + * + * Vacuum may process an index several times: a bulkdelete pass per index + * scan cycle plus a final cleanup pass, possibly spread across parallel + * workers. Each pass adds its elapsed and delay time here, accumulating + * into the index's total_vacuum_time or total_autovacuum_time, mirroring + * the table-level counters. The caller says whether this is autovacuum: + * parallel workers of an autovacuum leader are regular background workers, + * so AmAutoVacuumWorkerProcess() cannot be relied upon here. + */ +void +pgstat_report_index_vacuum_time(Relation rel, PgStat_Counter elapsedtime, + PgStat_Counter delaytime, bool is_autovacuum) +{ + PgStat_EntryRef *entry_ref; + PgStatShared_Index *shidxentry; + PgStat_StatIdxEntry *idxentry; + Oid dboid = (rel->rd_rel->relisshared ? InvalidOid : MyDatabaseId); + + if (!pgstat_track_counts) + return; + + /* block acquiring lock for the same reason as pgstat_report_autovac() */ + entry_ref = pgstat_get_entry_ref_locked(PGSTAT_KIND_INDEX, dboid, + RelationGetRelid(rel), false); + shidxentry = (PgStatShared_Index *) entry_ref->shared_stats; + idxentry = &shidxentry->stats; + + if (is_autovacuum) + { + idxentry->total_autovacuum_time += elapsedtime; + idxentry->total_autovacuum_delay_time += delaytime; + } + else + { + idxentry->total_vacuum_time += elapsedtime; + idxentry->total_vacuum_delay_time += delaytime; + } + + pgstat_unlock_entry(entry_ref); +} + /* * Callback to reset the timestamp on an index stats entry. */ diff --git a/src/backend/utils/activity/pgstat_relation.c b/src/backend/utils/activity/pgstat_relation.c index 5c70543ba88..59b18312903 100644 --- a/src/backend/utils/activity/pgstat_relation.c +++ b/src/backend/utils/activity/pgstat_relation.c @@ -261,7 +261,8 @@ pgstat_drop_relation(Relation rel) */ void pgstat_report_vacuum(Relation rel, PgStat_Counter livetuples, - PgStat_Counter deadtuples, TimestampTz starttime) + PgStat_Counter deadtuples, TimestampTz starttime, + PgStat_Counter delaytime) { PgStat_EntryRef *entry_ref; PgStatShared_Relation *shtabentry; @@ -304,16 +305,39 @@ pgstat_report_vacuum(Relation rel, PgStat_Counter livetuples, tabentry->last_autovacuum_time = ts; tabentry->autovacuum_count++; tabentry->total_autovacuum_time += elapsedtime; + tabentry->total_autovacuum_delay_time += delaytime; } else { tabentry->last_vacuum_time = ts; tabentry->vacuum_count++; tabentry->total_vacuum_time += elapsedtime; + tabentry->total_vacuum_delay_time += delaytime; } pgstat_unlock_entry(entry_ref); + /* + * Accumulate the same times into the database-wide totals. Index + * processing happens inside the table's run, so per-index times reported + * via pgstat_report_index_vacuum_time() are not added here again. The + * database entry is stored in microseconds, as its other time counters. + */ + { + PgStat_StatDBEntry *dbentry = pgstat_prep_database_pending(dboid); + + if (AmAutoVacuumWorkerProcess()) + { + dbentry->total_autovacuum_time += elapsedtime * 1000; + dbentry->total_autovacuum_delay_time += delaytime * 1000; + } + else + { + dbentry->total_vacuum_time += elapsedtime * 1000; + dbentry->total_vacuum_delay_time += delaytime * 1000; + } + } + /* * Flush IO statistics now. pgstat_report_stat() will flush IO stats, * however this will not be called until after an entire autovacuum cycle diff --git a/src/backend/utils/adt/pgstatfuncs.c b/src/backend/utils/adt/pgstatfuncs.c index 64b6f60516c..669857a5347 100644 --- a/src/backend/utils/adt/pgstatfuncs.c +++ b/src/backend/utils/adt/pgstatfuncs.c @@ -170,6 +170,43 @@ PG_STAT_GET_RELENTRY_FLOAT8(total_analyze_time) /* pg_stat_get_total_autoanalyze_time */ PG_STAT_GET_RELENTRY_FLOAT8(total_autoanalyze_time) +/* pg_stat_get_total_vacuum_delay_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_vacuum_delay_time) + +/* pg_stat_get_total_autovacuum_delay_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_autovacuum_delay_time) + +/* + * Accessor macro for float8 fields of index stats entries. + */ +#define PG_STAT_GET_IDXENTRY_FLOAT8(stat) \ +Datum \ +CppConcat(pg_stat_get_idx_,stat)(PG_FUNCTION_ARGS) \ +{ \ + Oid relid = PG_GETARG_OID(0); \ + double result; \ + PgStat_StatIdxEntry *idxentry; \ + \ + if ((idxentry = pgstat_fetch_stat_idxentry(relid)) == NULL) \ + result = 0; \ + else \ + result = (double) (idxentry->stat); \ + \ + PG_RETURN_FLOAT8(result); \ +} + +/* pg_stat_get_idx_total_vacuum_time */ +PG_STAT_GET_IDXENTRY_FLOAT8(total_vacuum_time) + +/* pg_stat_get_idx_total_autovacuum_time */ +PG_STAT_GET_IDXENTRY_FLOAT8(total_autovacuum_time) + +/* pg_stat_get_idx_total_vacuum_delay_time */ +PG_STAT_GET_IDXENTRY_FLOAT8(total_vacuum_delay_time) + +/* pg_stat_get_idx_total_autovacuum_delay_time */ +PG_STAT_GET_IDXENTRY_FLOAT8(total_autovacuum_delay_time) + #define PG_STAT_GET_RELENTRY_TIMESTAMPTZ(stat) \ Datum \ CppConcat(pg_stat_get_,stat)(PG_FUNCTION_ARGS) \ @@ -1301,6 +1338,18 @@ PG_STAT_GET_DBENTRY_FLOAT8_MS(blk_write_time) /* pg_stat_get_db_idle_in_transaction_time */ PG_STAT_GET_DBENTRY_FLOAT8_MS(idle_in_transaction_time) +/* pg_stat_get_db_total_vacuum_time */ +PG_STAT_GET_DBENTRY_FLOAT8_MS(total_vacuum_time) + +/* pg_stat_get_db_total_autovacuum_time */ +PG_STAT_GET_DBENTRY_FLOAT8_MS(total_autovacuum_time) + +/* pg_stat_get_db_total_vacuum_delay_time */ +PG_STAT_GET_DBENTRY_FLOAT8_MS(total_vacuum_delay_time) + +/* pg_stat_get_db_total_autovacuum_delay_time */ +PG_STAT_GET_DBENTRY_FLOAT8_MS(total_autovacuum_delay_time) + /* pg_stat_get_db_session_time */ PG_STAT_GET_DBENTRY_FLOAT8_MS(session_time) diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat index f46427258e3..64813a65274 100644 --- a/src/include/catalog/pg_proc.dat +++ b/src/include/catalog/pg_proc.dat @@ -5923,6 +5923,30 @@ proname => 'pg_stat_get_db_blk_write_time', provolatile => 's', proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', prosrc => 'pg_stat_get_db_blk_write_time' }, +{ oid => '8685', descr => 'total vacuum delay time, in milliseconds', + proname => 'pg_stat_get_total_vacuum_delay_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_total_vacuum_delay_time' }, +{ oid => '8686', descr => 'total autovacuum delay time, in milliseconds', + proname => 'pg_stat_get_total_autovacuum_delay_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_total_autovacuum_delay_time' }, +{ oid => '8687', descr => 'statistics: total vacuum time of tables in database, in milliseconds', + proname => 'pg_stat_get_db_total_vacuum_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_db_total_vacuum_time' }, +{ oid => '8688', descr => 'statistics: total autovacuum time of tables in database, in milliseconds', + proname => 'pg_stat_get_db_total_autovacuum_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_db_total_autovacuum_time' }, +{ oid => '8689', descr => 'statistics: total vacuum delay time in database, in milliseconds', + proname => 'pg_stat_get_db_total_vacuum_delay_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_db_total_vacuum_delay_time' }, +{ oid => '8690', descr => 'statistics: total autovacuum delay time in database, in milliseconds', + proname => 'pg_stat_get_db_total_autovacuum_delay_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_db_total_autovacuum_delay_time' }, { oid => '6185', descr => 'statistics: session time, in milliseconds', proname => 'pg_stat_get_db_session_time', provolatile => 's', proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', @@ -6271,6 +6295,26 @@ proname => 'pg_stat_get_idx_stat_reset_time', provolatile => 's', proparallel => 'r', prorettype => 'timestamptz', proargtypes => 'oid', prosrc => 'pg_stat_get_idx_stat_reset_time' }, +{ oid => '8695', + descr => 'statistics: total vacuum time for index, in milliseconds', + proname => 'pg_stat_get_idx_total_vacuum_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_idx_total_vacuum_time' }, +{ oid => '8696', + descr => 'statistics: total autovacuum time for index, in milliseconds', + proname => 'pg_stat_get_idx_total_autovacuum_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_idx_total_autovacuum_time' }, +{ oid => '8697', + descr => 'statistics: total vacuum delay time for index, in milliseconds', + proname => 'pg_stat_get_idx_total_vacuum_delay_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_idx_total_vacuum_delay_time' }, +{ oid => '8698', + descr => 'statistics: total autovacuum delay time for index, in milliseconds', + proname => 'pg_stat_get_idx_total_autovacuum_delay_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_idx_total_autovacuum_delay_time' }, { oid => '8458', descr => 'statistics: number of scans done for index in current transaction', proname => 'pg_stat_get_xact_idx_numscans', provolatile => 'v', diff --git a/src/include/commands/vacuum.h b/src/include/commands/vacuum.h index 6e3c912bf5c..21cc777fa1f 100644 --- a/src/include/commands/vacuum.h +++ b/src/include/commands/vacuum.h @@ -367,6 +367,7 @@ extern PGDLLIMPORT double vacuum_cost_delay; extern PGDLLIMPORT int vacuum_cost_limit; extern PGDLLIMPORT int64 parallel_vacuum_worker_delay_ns; +extern PGDLLIMPORT double VacuumDelayTime; /* in commands/vacuum.c */ extern void ExecVacuum(ParseState *pstate, VacuumStmt *vacstmt, bool isTopLevel); diff --git a/src/include/pgstat.h b/src/include/pgstat.h index 187d82c96fe..62f45eb310e 100644 --- a/src/include/pgstat.h +++ b/src/include/pgstat.h @@ -456,6 +456,17 @@ typedef struct PgStat_StatDBEntry PgStat_Counter parallel_workers_to_launch; PgStat_Counter parallel_workers_launched; + /* + * Cumulative time vacuums spent processing tables of this database and + * sleeping in cost-based delay points, in microseconds (the delay parts + * advance only when track_cost_delay_timing is enabled). Times of index + * processing are included in the owning table's run. + */ + PgStat_Counter total_vacuum_time; + PgStat_Counter total_autovacuum_time; + PgStat_Counter total_vacuum_delay_time; + PgStat_Counter total_autovacuum_delay_time; + TimestampTz stat_reset_timestamp; } PgStat_StatDBEntry; @@ -541,6 +552,14 @@ typedef struct PgStat_StatTabEntry PgStat_Counter total_analyze_time; PgStat_Counter total_autoanalyze_time; + /* + * Time slept in cost-based vacuum delay points while vacuuming this + * relation, in milliseconds; nonzero only when track_cost_delay_timing + * is enabled. + */ + PgStat_Counter total_vacuum_delay_time; + PgStat_Counter total_autovacuum_delay_time; + TimestampTz stat_reset_time; } PgStat_StatTabEntry; @@ -555,6 +574,21 @@ typedef struct PgStat_StatIdxEntry PgStat_Counter blocks_fetched; PgStat_Counter blocks_hit; + /* + * Cumulative time spent vacuuming this index, in milliseconds, + * accumulated over the bulkdelete and cleanup passes of the vacuums of + * the owning table (including the passes done by parallel workers). + */ + PgStat_Counter total_vacuum_time; + PgStat_Counter total_autovacuum_time; + + /* + * Time slept in cost-based vacuum delay points during those passes, in + * milliseconds; nonzero only when track_cost_delay_timing is enabled. + */ + PgStat_Counter total_vacuum_delay_time; + PgStat_Counter total_autovacuum_delay_time; + TimestampTz stat_reset_time; } PgStat_StatIdxEntry; @@ -782,7 +816,12 @@ extern void pgstat_unlink_relation(Relation rel); extern void pgstat_report_vacuum(Relation rel, PgStat_Counter livetuples, PgStat_Counter deadtuples, - TimestampTz starttime); + TimestampTz starttime, + PgStat_Counter delaytime); +extern void pgstat_report_index_vacuum_time(Relation rel, + PgStat_Counter elapsedtime, + PgStat_Counter delaytime, + bool is_autovacuum); extern void pgstat_report_analyze(Relation rel, PgStat_Counter livetuples, PgStat_Counter deadtuples, bool resetcounter, TimestampTz starttime); diff --git a/src/test/modules/test_misc/meson.build b/src/test/modules/test_misc/meson.build index 5d81f5b13be..f5f80e64062 100644 --- a/src/test/modules/test_misc/meson.build +++ b/src/test/modules/test_misc/meson.build @@ -24,6 +24,7 @@ tests += { 't/013_temp_obj_multisession.pl', 't/014_log_statement_max_length.pl', 't/015_temp_schema_exit_deferrable.pl', + 't/016_index_vacuum_time.pl', ], # The injection points are cluster-wide, so disable installcheck 'runningcheck': false, diff --git a/src/test/modules/test_misc/t/016_index_vacuum_time.pl b/src/test/modules/test_misc/t/016_index_vacuum_time.pl new file mode 100644 index 00000000000..36360b40a07 --- /dev/null +++ b/src/test/modules/test_misc/t/016_index_vacuum_time.pl @@ -0,0 +1,72 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# Test the total_vacuum_time counter of pg_stat_all_indexes: the time vacuum +# spent processing each index, accumulated over bulkdelete and cleanup passes, +# mirroring the table-level counter in pg_stat_all_tables. + +use strict; +use warnings FATAL => 'all'; +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; + +my $node = PostgreSQL::Test::Cluster->new('main'); +$node->init; +$node->append_conf( + 'postgresql.conf', qq[ +autovacuum = off +track_cost_delay_timing = on +]); +$node->start; + +# Enough rows that the bulkdelete pass over the index takes measurable time; +# a small vacuum_cost_delay adds deterministic delay time on fast machines. +$node->safe_psql( + 'postgres', qq[ +CREATE TABLE vactime_t (id int PRIMARY KEY, v text) WITH (autovacuum_enabled = off); +INSERT INTO vactime_t SELECT g, repeat('x', 10) FROM generate_series(1, 100000) g; +DELETE FROM vactime_t WHERE id % 2 = 0; +]); +$node->safe_psql( + 'postgres', qq[ +SET vacuum_cost_delay = '1ms'; +SET vacuum_cost_limit = 200; +VACUUM vactime_t; +]); + +# The upper bound guards against garbage such as an epoch-based elapsed time +# leaking into the counter. +is( $node->safe_psql( + 'postgres', qq[ +SELECT total_vacuum_time > 0 AND total_vacuum_time < 600000 + FROM pg_stat_all_indexes WHERE indexrelname = 'vactime_t_pkey']), + 't', + 'total_vacuum_time advanced sanely for the index in pg_stat_all_indexes'); + +is( $node->safe_psql( + 'postgres', qq[ +SELECT total_vacuum_delay_time > 0 AND total_vacuum_delay_time <= total_vacuum_time + FROM pg_stat_all_indexes WHERE indexrelname = 'vactime_t_pkey']), + 't', + 'total_vacuum_delay_time advanced and not above total_vacuum_time'); + +is( $node->safe_psql( + 'postgres', qq[ +SELECT total_autovacuum_time = 0 FROM pg_stat_all_indexes + WHERE indexrelname = 'vactime_t_pkey']), + 't', + 'manual vacuum did not count into total_autovacuum_time'); + +# The same run must have accumulated into the database-wide totals. +is( $node->safe_psql( + 'postgres', qq[ +SELECT total_vacuum_time > 0 AND total_vacuum_time < 600000 + AND total_vacuum_delay_time > 0 + AND total_vacuum_delay_time <= total_vacuum_time + FROM pg_stat_database WHERE datname = current_database()]), + 't', + 'database-wide vacuum times advanced sanely in pg_stat_database'); + +$node->stop; + +done_testing(); diff --git a/src/test/regress/expected/rules.out b/src/test/regress/expected/rules.out index 4a8cc759d7b..13f490cf993 100644 --- a/src/test/regress/expected/rules.out +++ b/src/test/regress/expected/rules.out @@ -1810,6 +1810,10 @@ pg_stat_all_indexes| SELECT c.oid AS relid, pg_stat_get_idx_lastscan(i.oid) AS last_idx_scan, pg_stat_get_idx_tuples_returned(i.oid) AS idx_tup_read, pg_stat_get_idx_tuples_fetched(i.oid) AS idx_tup_fetch, + pg_stat_get_idx_total_vacuum_time(i.oid) AS total_vacuum_time, + pg_stat_get_idx_total_autovacuum_time(i.oid) AS total_autovacuum_time, + pg_stat_get_idx_total_vacuum_delay_time(i.oid) AS total_vacuum_delay_time, + pg_stat_get_idx_total_autovacuum_delay_time(i.oid) AS total_autovacuum_delay_time, pg_stat_get_idx_stat_reset_time(i.oid) AS stats_reset FROM (((pg_class c JOIN pg_index x ON ((c.oid = x.indrelid))) @@ -1846,6 +1850,8 @@ pg_stat_all_tables| SELECT c.oid AS relid, pg_stat_get_total_autovacuum_time(c.oid) AS total_autovacuum_time, pg_stat_get_total_analyze_time(c.oid) AS total_analyze_time, pg_stat_get_total_autoanalyze_time(c.oid) AS total_autoanalyze_time, + pg_stat_get_total_vacuum_delay_time(c.oid) AS total_vacuum_delay_time, + pg_stat_get_total_autovacuum_delay_time(c.oid) AS total_autovacuum_delay_time, pg_stat_get_stat_reset_time(c.oid) AS stats_reset FROM ((pg_class c LEFT JOIN pg_index i ON ((c.oid = i.indrelid))) @@ -1913,6 +1919,10 @@ pg_stat_database| SELECT oid AS datid, pg_stat_get_db_checksum_last_failure(oid) AS checksum_last_failure, pg_stat_get_db_blk_read_time(oid) AS blk_read_time, pg_stat_get_db_blk_write_time(oid) AS blk_write_time, + pg_stat_get_db_total_vacuum_time(oid) AS total_vacuum_time, + pg_stat_get_db_total_autovacuum_time(oid) AS total_autovacuum_time, + pg_stat_get_db_total_vacuum_delay_time(oid) AS total_vacuum_delay_time, + pg_stat_get_db_total_autovacuum_delay_time(oid) AS total_autovacuum_delay_time, pg_stat_get_db_session_time(oid) AS session_time, pg_stat_get_db_active_time(oid) AS active_time, pg_stat_get_db_idle_in_transaction_time(oid) AS idle_in_transaction_time, @@ -2336,6 +2346,10 @@ pg_stat_sys_indexes| SELECT relid, last_idx_scan, idx_tup_read, idx_tup_fetch, + total_vacuum_time, + total_autovacuum_time, + total_vacuum_delay_time, + total_autovacuum_delay_time, stats_reset FROM pg_stat_all_indexes WHERE ((schemaname = ANY (ARRAY['pg_catalog'::name, 'information_schema'::name])) OR (schemaname ~ '^pg_toast'::text)); @@ -2369,6 +2383,8 @@ pg_stat_sys_tables| SELECT relid, total_autovacuum_time, total_analyze_time, total_autoanalyze_time, + total_vacuum_delay_time, + total_autovacuum_delay_time, stats_reset FROM pg_stat_all_tables WHERE ((schemaname = ANY (ARRAY['pg_catalog'::name, 'information_schema'::name])) OR (schemaname ~ '^pg_toast'::text)); @@ -2391,6 +2407,10 @@ pg_stat_user_indexes| SELECT relid, last_idx_scan, idx_tup_read, idx_tup_fetch, + total_vacuum_time, + total_autovacuum_time, + total_vacuum_delay_time, + total_autovacuum_delay_time, stats_reset FROM pg_stat_all_indexes WHERE ((schemaname <> ALL (ARRAY['pg_catalog'::name, 'information_schema'::name])) AND (schemaname !~ '^pg_toast'::text)); @@ -2424,6 +2444,8 @@ pg_stat_user_tables| SELECT relid, total_autovacuum_time, total_analyze_time, total_autoanalyze_time, + total_vacuum_delay_time, + total_autovacuum_delay_time, stats_reset FROM pg_stat_all_tables WHERE ((schemaname <> ALL (ARRAY['pg_catalog'::name, 'information_schema'::name])) AND (schemaname !~ '^pg_toast'::text)); -- 2.50.1 (Apple Git-155)