Hi,
On Mon, Feb 10, 2025 at 02:52:46PM -0600, Nathan Bossart wrote:
> Here is what I have prepared for commit. Other expanding the commit
> messages, I've modified 0001 to just add a parameter to
> vacuum_delay_point() to indicate whether this is a vacuum or analyze. I
> was worried that adding an analyze_delay_point() could cause third-party
> code to miss this change. We want such code to correctly indicate the type
> of operation so that the progress views work for them, too.
Good point, that makes fully sense. v17 LGTM.
> Off-list, I've asked Bertrand to gauge the feasibility of adding this
> information to the autovacuum logs and to VACUUM/ANALYZE (VERBOSE). IMHO
> those are natural places to surface this information, and I want to ensure
> that we're not painting ourselves into a corner with the approach we're
> using for the progress views.
Yeah, I looked at it and that looks as simmple as 0003 attached (as that's the
leader that is doing the report in case of parallel workers being used).
0001 and 0002 remain unchanged.
Regards,
--
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com
>From f4640855bbeb0b2fb63e8ba5afff61c04302fa40 Mon Sep 17 00:00:00 2001
From: Nathan Bossart <nat...@postgresql.org>
Date: Mon, 10 Feb 2025 11:41:22 -0600
Subject: [PATCH v17 1/3] Add is_analyze parameter to vacuum_delay_point().
This function is used in both vacuum and analyze code paths, and a
follow-up commit will require distinguishing between the two. This
commit forces callers to declare whether they are being used for
vacuum or analyze, but it does not use that information for
anything yet.
Author: Nathan Bossart <nathandboss...@gmail.com>
Co-authored-by: Bertrand Drouvot <bertranddrouvot...@gmail.com>
Discussion: https://postgr.es/m/ZmaXmWDL829fzAVX%40ip-10-97-1-34.eu-west-3.compute.internal
---
contrib/bloom/blvacuum.c | 4 ++--
contrib/file_fdw/file_fdw.c | 2 +-
src/backend/access/gin/ginfast.c | 6 +++---
src/backend/access/gin/ginvacuum.c | 6 +++---
src/backend/access/gist/gistvacuum.c | 2 +-
src/backend/access/hash/hash.c | 2 +-
src/backend/access/heap/vacuumlazy.c | 4 ++--
src/backend/access/nbtree/nbtree.c | 2 +-
src/backend/access/spgist/spgvacuum.c | 4 ++--
src/backend/commands/analyze.c | 10 +++++-----
src/backend/commands/vacuum.c | 2 +-
src/backend/tsearch/ts_typanalyze.c | 2 +-
src/backend/utils/adt/array_typanalyze.c | 2 +-
src/backend/utils/adt/rangetypes_typanalyze.c | 2 +-
src/include/commands/vacuum.h | 2 +-
15 files changed, 26 insertions(+), 26 deletions(-)
7.5% contrib/bloom/
3.6% contrib/file_fdw/
22.9% src/backend/access/gin/
3.6% src/backend/access/gist/
3.7% src/backend/access/hash/
7.5% src/backend/access/heap/
3.6% src/backend/access/nbtree/
7.3% src/backend/access/spgist/
22.8% src/backend/commands/
3.6% src/backend/tsearch/
7.3% src/backend/utils/adt/
6.1% src/include/commands/
diff --git a/contrib/bloom/blvacuum.c b/contrib/bloom/blvacuum.c
index 7e1db0b52fc..86b15a75f6f 100644
--- a/contrib/bloom/blvacuum.c
+++ b/contrib/bloom/blvacuum.c
@@ -57,7 +57,7 @@ blbulkdelete(IndexVacuumInfo *info, IndexBulkDeleteResult *stats,
*itupPtr,
*itupEnd;
- vacuum_delay_point();
+ vacuum_delay_point(false);
buffer = ReadBufferExtended(index, MAIN_FORKNUM, blkno,
RBM_NORMAL, info->strategy);
@@ -187,7 +187,7 @@ blvacuumcleanup(IndexVacuumInfo *info, IndexBulkDeleteResult *stats)
Buffer buffer;
Page page;
- vacuum_delay_point();
+ vacuum_delay_point(false);
buffer = ReadBufferExtended(index, MAIN_FORKNUM, blkno,
RBM_NORMAL, info->strategy);
diff --git a/contrib/file_fdw/file_fdw.c b/contrib/file_fdw/file_fdw.c
index 678e754b2b9..0655bf532a0 100644
--- a/contrib/file_fdw/file_fdw.c
+++ b/contrib/file_fdw/file_fdw.c
@@ -1237,7 +1237,7 @@ file_acquire_sample_rows(Relation onerel, int elevel,
for (;;)
{
/* Check for user-requested abort or sleep */
- vacuum_delay_point();
+ vacuum_delay_point(true);
/* Fetch next row */
MemoryContextReset(tupcontext);
diff --git a/src/backend/access/gin/ginfast.c b/src/backend/access/gin/ginfast.c
index 4ab815fefe0..cc5d046c4b0 100644
--- a/src/backend/access/gin/ginfast.c
+++ b/src/backend/access/gin/ginfast.c
@@ -892,7 +892,7 @@ ginInsertCleanup(GinState *ginstate, bool full_clean,
*/
processPendingPage(&accum, &datums, page, FirstOffsetNumber);
- vacuum_delay_point();
+ vacuum_delay_point(false);
/*
* Is it time to flush memory to disk? Flush if we are at the end of
@@ -929,7 +929,7 @@ ginInsertCleanup(GinState *ginstate, bool full_clean,
{
ginEntryInsert(ginstate, attnum, key, category,
list, nlist, NULL);
- vacuum_delay_point();
+ vacuum_delay_point(false);
}
/*
@@ -1002,7 +1002,7 @@ ginInsertCleanup(GinState *ginstate, bool full_clean,
/*
* Read next page in pending list
*/
- vacuum_delay_point();
+ vacuum_delay_point(false);
buffer = ReadBuffer(index, blkno);
LockBuffer(buffer, GIN_SHARE);
page = BufferGetPage(buffer);
diff --git a/src/backend/access/gin/ginvacuum.c b/src/backend/access/gin/ginvacuum.c
index d98c54b7cf7..533c37b3c5f 100644
--- a/src/backend/access/gin/ginvacuum.c
+++ b/src/backend/access/gin/ginvacuum.c
@@ -662,12 +662,12 @@ ginbulkdelete(IndexVacuumInfo *info, IndexBulkDeleteResult *stats,
UnlockReleaseBuffer(buffer);
}
- vacuum_delay_point();
+ vacuum_delay_point(false);
for (i = 0; i < nRoot; i++)
{
ginVacuumPostingTree(&gvs, rootOfPostingTree[i]);
- vacuum_delay_point();
+ vacuum_delay_point(false);
}
if (blkno == InvalidBlockNumber) /* rightmost page */
@@ -748,7 +748,7 @@ ginvacuumcleanup(IndexVacuumInfo *info, IndexBulkDeleteResult *stats)
Buffer buffer;
Page page;
- vacuum_delay_point();
+ vacuum_delay_point(false);
buffer = ReadBufferExtended(index, MAIN_FORKNUM, blkno,
RBM_NORMAL, info->strategy);
diff --git a/src/backend/access/gist/gistvacuum.c b/src/backend/access/gist/gistvacuum.c
index fe0bfb781ca..dd0d9d5006c 100644
--- a/src/backend/access/gist/gistvacuum.c
+++ b/src/backend/access/gist/gistvacuum.c
@@ -283,7 +283,7 @@ restart:
recurse_to = InvalidBlockNumber;
/* call vacuum_delay_point while not holding any buffer lock */
- vacuum_delay_point();
+ vacuum_delay_point(false);
buffer = ReadBufferExtended(rel, MAIN_FORKNUM, blkno, RBM_NORMAL,
info->strategy);
diff --git a/src/backend/access/hash/hash.c b/src/backend/access/hash/hash.c
index 63b568e7f24..4167b33e683 100644
--- a/src/backend/access/hash/hash.c
+++ b/src/backend/access/hash/hash.c
@@ -716,7 +716,7 @@ hashbucketcleanup(Relation rel, Bucket cur_bucket, Buffer bucket_buf,
bool retain_pin = false;
bool clear_dead_marking = false;
- vacuum_delay_point();
+ vacuum_delay_point(false);
page = BufferGetPage(buf);
opaque = HashPageGetOpaque(page);
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 075af385cd1..e4d6d654c0a 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -946,7 +946,7 @@ lazy_scan_heap(LVRelState *vacrel)
update_vacuum_error_info(vacrel, NULL, VACUUM_ERRCB_PHASE_SCAN_HEAP,
blkno, InvalidOffsetNumber);
- vacuum_delay_point();
+ vacuum_delay_point(false);
/*
* Regularly check if wraparound failsafe should trigger.
@@ -2275,7 +2275,7 @@ lazy_vacuum_heap_rel(LVRelState *vacrel)
OffsetNumber offsets[MaxOffsetNumber];
int num_offsets;
- vacuum_delay_point();
+ vacuum_delay_point(false);
blkno = iter_result->blkno;
vacrel->blkno = blkno;
diff --git a/src/backend/access/nbtree/nbtree.c b/src/backend/access/nbtree/nbtree.c
index 971405e89af..dc244ae24c7 100644
--- a/src/backend/access/nbtree/nbtree.c
+++ b/src/backend/access/nbtree/nbtree.c
@@ -1137,7 +1137,7 @@ backtrack:
backtrack_to = P_NONE;
/* call vacuum_delay_point while not holding any buffer lock */
- vacuum_delay_point();
+ vacuum_delay_point(false);
/*
* We can't use _bt_getbuf() here because it always applies
diff --git a/src/backend/access/spgist/spgvacuum.c b/src/backend/access/spgist/spgvacuum.c
index 894aefa19e1..1c52f6528ad 100644
--- a/src/backend/access/spgist/spgvacuum.c
+++ b/src/backend/access/spgist/spgvacuum.c
@@ -625,7 +625,7 @@ spgvacuumpage(spgBulkDeleteState *bds, BlockNumber blkno)
Page page;
/* call vacuum_delay_point while not holding any buffer lock */
- vacuum_delay_point();
+ vacuum_delay_point(false);
buffer = ReadBufferExtended(index, MAIN_FORKNUM, blkno,
RBM_NORMAL, bds->info->strategy);
@@ -704,7 +704,7 @@ spgprocesspending(spgBulkDeleteState *bds)
continue; /* ignore already-done items */
/* call vacuum_delay_point while not holding any buffer lock */
- vacuum_delay_point();
+ vacuum_delay_point(false);
/* examine the referenced page */
blkno = ItemPointerGetBlockNumber(&pitem->tid);
diff --git a/src/backend/commands/analyze.c b/src/backend/commands/analyze.c
index e5ab207d2ec..e4302f4cdb2 100644
--- a/src/backend/commands/analyze.c
+++ b/src/backend/commands/analyze.c
@@ -915,7 +915,7 @@ compute_index_stats(Relation onerel, double totalrows,
{
HeapTuple heapTuple = rows[rowno];
- vacuum_delay_point();
+ vacuum_delay_point(true);
/*
* Reset the per-tuple context each time, to reclaim any cruft
@@ -1238,7 +1238,7 @@ acquire_sample_rows(Relation onerel, int elevel,
/* Outer loop over blocks to sample */
while (table_scan_analyze_next_block(scan, stream))
{
- vacuum_delay_point();
+ vacuum_delay_point(true);
while (table_scan_analyze_next_tuple(scan, OldestXmin, &liverows, &deadrows, slot))
{
@@ -1970,7 +1970,7 @@ compute_trivial_stats(VacAttrStatsP stats,
Datum value;
bool isnull;
- vacuum_delay_point();
+ vacuum_delay_point(true);
value = fetchfunc(stats, i, &isnull);
@@ -2086,7 +2086,7 @@ compute_distinct_stats(VacAttrStatsP stats,
int firstcount1,
j;
- vacuum_delay_point();
+ vacuum_delay_point(true);
value = fetchfunc(stats, i, &isnull);
@@ -2433,7 +2433,7 @@ compute_scalar_stats(VacAttrStatsP stats,
Datum value;
bool isnull;
- vacuum_delay_point();
+ vacuum_delay_point(true);
value = fetchfunc(stats, i, &isnull);
diff --git a/src/backend/commands/vacuum.c b/src/backend/commands/vacuum.c
index e6745e6145c..5e394c151c9 100644
--- a/src/backend/commands/vacuum.c
+++ b/src/backend/commands/vacuum.c
@@ -2358,7 +2358,7 @@ vac_close_indexes(int nindexes, Relation *Irel, LOCKMODE lockmode)
* typically once per page processed.
*/
void
-vacuum_delay_point(void)
+vacuum_delay_point(bool is_analyze)
{
double msec = 0;
diff --git a/src/backend/tsearch/ts_typanalyze.c b/src/backend/tsearch/ts_typanalyze.c
index 1494da1c9d3..c5a71331ce8 100644
--- a/src/backend/tsearch/ts_typanalyze.c
+++ b/src/backend/tsearch/ts_typanalyze.c
@@ -204,7 +204,7 @@ compute_tsvector_stats(VacAttrStats *stats,
char *lexemesptr;
int j;
- vacuum_delay_point();
+ vacuum_delay_point(true);
value = fetchfunc(stats, vector_no, &isnull);
diff --git a/src/backend/utils/adt/array_typanalyze.c b/src/backend/utils/adt/array_typanalyze.c
index 44a6eb5dad0..6f61629b977 100644
--- a/src/backend/utils/adt/array_typanalyze.c
+++ b/src/backend/utils/adt/array_typanalyze.c
@@ -314,7 +314,7 @@ compute_array_stats(VacAttrStats *stats, AnalyzeAttrFetchFunc fetchfunc,
int distinct_count;
bool count_item_found;
- vacuum_delay_point();
+ vacuum_delay_point(true);
value = fetchfunc(stats, array_no, &isnull);
if (isnull)
diff --git a/src/backend/utils/adt/rangetypes_typanalyze.c b/src/backend/utils/adt/rangetypes_typanalyze.c
index 9dc73af1992..a18196d8a34 100644
--- a/src/backend/utils/adt/rangetypes_typanalyze.c
+++ b/src/backend/utils/adt/rangetypes_typanalyze.c
@@ -167,7 +167,7 @@ compute_range_stats(VacAttrStats *stats, AnalyzeAttrFetchFunc fetchfunc,
upper;
float8 length;
- vacuum_delay_point();
+ vacuum_delay_point(true);
value = fetchfunc(stats, range_no, &isnull);
if (isnull)
diff --git a/src/include/commands/vacuum.h b/src/include/commands/vacuum.h
index 12d0b61950d..b884304dfe7 100644
--- a/src/include/commands/vacuum.h
+++ b/src/include/commands/vacuum.h
@@ -339,7 +339,7 @@ extern bool vacuum_get_cutoffs(Relation rel, const VacuumParams *params,
struct VacuumCutoffs *cutoffs);
extern bool vacuum_xid_failsafe_check(const struct VacuumCutoffs *cutoffs);
extern void vac_update_datfrozenxid(void);
-extern void vacuum_delay_point(void);
+extern void vacuum_delay_point(bool is_analyze);
extern bool vacuum_is_permitted_for_relation(Oid relid, Form_pg_class reltuple,
bits32 options);
extern Relation vacuum_open_relation(Oid relid, RangeVar *relation,
--
2.34.1
>From 6b7966d2ca736a82345b87edb5fa3bf457d4d9bf Mon Sep 17 00:00:00 2001
From: Nathan Bossart <nat...@postgresql.org>
Date: Mon, 10 Feb 2025 14:25:02 -0600
Subject: [PATCH v17 2/3] Add cost-based delay time to progress views.
This commit adds the amount of time spent sleeping due to
cost-based delay to the pg_stat_progress_vacuum and
pg_stat_progress_analyze system views. A new configuration
parameter named track_cost_delay_timing, which is off by default,
controls whether this information is gathered. For vacuum, the
reported value includes the time that any associated parallel
workers have slept. However, parallel workers only report their
sleep time no more frequently than once per second to avoid
overloading the leader process.
XXX: NEEDS CATVERSION BUMP
Author: Bertrand Drouvot <bertranddrouvot...@gmail.com>
Co-authored-by: Nathan Bossart <nathandboss...@gmail.com>
Reviewed-by: Sami Imseih <samims...@gmail.com>
Reviewed-by: Robert Haas <robertmh...@gmail.com>
Reviewed-by: Masahiko Sawada <sawada.m...@gmail.com>
Reviewed-by: Masahiro Ikeda <ikeda...@oss.nttdata.com>
Reviewed-by: Dilip Kumar <dilipbal...@gmail.com>
Reviewed-by: Sergei Kornilov <s...@zsrv.org>
Discussion: https://postgr.es/m/ZmaXmWDL829fzAVX%40ip-10-97-1-34.eu-west-3.compute.internal
---
doc/src/sgml/config.sgml | 24 +++++++
doc/src/sgml/monitoring.sgml | 27 ++++++++
src/backend/catalog/system_views.sql | 6 +-
src/backend/commands/vacuum.c | 64 +++++++++++++++++++
src/backend/commands/vacuumparallel.c | 5 ++
src/backend/utils/misc/guc_tables.c | 9 +++
src/backend/utils/misc/postgresql.conf.sample | 1 +
src/include/commands/progress.h | 2 +
src/include/commands/vacuum.h | 3 +
src/test/regress/expected/rules.out | 6 +-
10 files changed, 143 insertions(+), 4 deletions(-)
42.1% doc/src/sgml/
5.6% src/backend/catalog/
38.5% src/backend/commands/
4.3% src/backend/utils/misc/
3.4% src/include/commands/
5.8% src/test/regress/expected/
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 38244409e3c..79a66ba7181 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -8246,6 +8246,30 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv;
</listitem>
</varlistentry>
+ <varlistentry id="guc-track-cost-delay-timing" xreflabel="track_cost_delay_timing">
+ <term><varname>track_cost_delay_timing</varname> (<type>boolean</type>)
+ <indexterm>
+ <primary><varname>track_cost_delay_timing</varname> configuration parameter</primary>
+ </indexterm>
+ </term>
+ <listitem>
+ <para>
+ Enables timing of cost-based vacuum delay (see
+ <xref linkend="runtime-config-resource-vacuum-cost"/>). This parameter
+ is off by default, as it will repeatedly query the operating system for
+ the current time, which may cause significant overhead on some
+ platforms. You can use the <xref linkend="pgtesttiming"/> tool to
+ measure the overhead of timing on your system. Cost-based vacuum delay
+ timing information is displayed in
+ <link linkend="vacuum-progress-reporting"><structname>pg_stat_progress_vacuum</structname></link>
+ and
+ <link linkend="analyze-progress-reporting"><structname>pg_stat_progress_analyze</structname></link>.
+ Only superusers and users with the appropriate <literal>SET</literal>
+ privilege can change this setting.
+ </para>
+ </listitem>
+ </varlistentry>
+
<varlistentry id="guc-track-io-timing" xreflabel="track_io_timing">
<term><varname>track_io_timing</varname> (<type>boolean</type>)
<indexterm>
diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml
index edc2470bcf9..928a6eb64b0 100644
--- a/doc/src/sgml/monitoring.sgml
+++ b/doc/src/sgml/monitoring.sgml
@@ -5606,6 +5606,18 @@ FROM pg_stat_get_backend_idset() AS backendid;
<literal>acquiring inherited sample rows</literal>.
</para></entry>
</row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>delay_time</structfield> <type>double precision</type>
+ </para>
+ <para>
+ Total time spent sleeping due to cost-based delay (see
+ <xref linkend="runtime-config-resource-vacuum-cost"/>, in milliseconds
+ (if <xref linkend="guc-track-cost-delay-timing"/> is enabled, otherwise
+ zero).
+ </para></entry>
+ </row>
</tbody>
</tgroup>
</table>
@@ -6531,6 +6543,21 @@ FROM pg_stat_get_backend_idset() AS backendid;
<literal>cleaning up indexes</literal>.
</para></entry>
</row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>delay_time</structfield> <type>double precision</type>
+ </para>
+ <para>
+ Total time spent sleeping due to cost-based delay (see
+ <xref linkend="runtime-config-resource-vacuum-cost"/>), in milliseconds
+ (if <xref linkend="guc-track-cost-delay-timing"/> is enabled, otherwise
+ zero). This includes the time that any associated parallel workers have
+ slept. However, parallel workers report their sleep time no more
+ frequently than once per second, so the reported value may be slightly
+ stale.
+ </para></entry>
+ </row>
</tbody>
</tgroup>
</table>
diff --git a/src/backend/catalog/system_views.sql b/src/backend/catalog/system_views.sql
index cddc3ea9b53..eff0990957e 100644
--- a/src/backend/catalog/system_views.sql
+++ b/src/backend/catalog/system_views.sql
@@ -1213,7 +1213,8 @@ CREATE VIEW pg_stat_progress_analyze AS
S.param5 AS ext_stats_computed,
S.param6 AS child_tables_total,
S.param7 AS child_tables_done,
- CAST(S.param8 AS oid) AS current_child_table_relid
+ CAST(S.param8 AS oid) AS current_child_table_relid,
+ S.param9 / 1000000::double precision AS delay_time
FROM pg_stat_get_progress_info('ANALYZE') AS S
LEFT JOIN pg_database D ON S.datid = D.oid;
@@ -1233,7 +1234,8 @@ CREATE VIEW pg_stat_progress_vacuum AS
S.param4 AS heap_blks_vacuumed, S.param5 AS index_vacuum_count,
S.param6 AS max_dead_tuple_bytes, S.param7 AS dead_tuple_bytes,
S.param8 AS num_dead_item_ids, S.param9 AS indexes_total,
- S.param10 AS indexes_processed
+ S.param10 AS indexes_processed,
+ S.param11 / 1000000::double precision AS delay_time
FROM pg_stat_get_progress_info('VACUUM') AS S
LEFT JOIN pg_database D ON S.datid = D.oid;
diff --git a/src/backend/commands/vacuum.c b/src/backend/commands/vacuum.c
index 5e394c151c9..4cba2e0a260 100644
--- a/src/backend/commands/vacuum.c
+++ b/src/backend/commands/vacuum.c
@@ -39,6 +39,7 @@
#include "catalog/pg_inherits.h"
#include "commands/cluster.h"
#include "commands/defrem.h"
+#include "commands/progress.h"
#include "commands/vacuum.h"
#include "miscadmin.h"
#include "nodes/makefuncs.h"
@@ -59,6 +60,12 @@
#include "utils/snapmgr.h"
#include "utils/syscache.h"
+/*
+ * Minimum interval for cost-based vacuum delay reports from a parallel worker.
+ * This aims to avoid sending too many messages and waking up the leader too
+ * frequently
+ */
+#define PARALLEL_VACUUM_DELAY_REPORT_INTERVAL_NS (NS_PER_S)
/*
* GUC parameters
@@ -69,6 +76,7 @@ int vacuum_multixact_freeze_min_age;
int vacuum_multixact_freeze_table_age;
int vacuum_failsafe_age;
int vacuum_multixact_failsafe_age;
+bool track_cost_delay_timing;
/*
* Variables for cost-based vacuum delay. The defaults differ between
@@ -79,6 +87,9 @@ int vacuum_multixact_failsafe_age;
double vacuum_cost_delay = 0;
int vacuum_cost_limit = 200;
+/* Variable for reporting cost-based vacuum delay from parallel workers. */
+int64 parallel_vacuum_worker_delay_ns = 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.
@@ -2401,13 +2412,66 @@ vacuum_delay_point(bool is_analyze)
/* Nap if appropriate */
if (msec > 0)
{
+ instr_time delay_start;
+
if (msec > vacuum_cost_delay * 4)
msec = vacuum_cost_delay * 4;
+ if (track_cost_delay_timing)
+ INSTR_TIME_SET_CURRENT(delay_start);
+
pgstat_report_wait_start(WAIT_EVENT_VACUUM_DELAY);
pg_usleep(msec * 1000);
pgstat_report_wait_end();
+ if (track_cost_delay_timing)
+ {
+ instr_time delay_end;
+ instr_time delay;
+
+ INSTR_TIME_SET_CURRENT(delay_end);
+ INSTR_TIME_SET_ZERO(delay);
+ INSTR_TIME_ACCUM_DIFF(delay, delay_end, delay_start);
+
+ /*
+ * For parallel workers, we only report the delay time every once
+ * in a while to avoid overloading the leader with messages and
+ * interrupts.
+ */
+ if (IsParallelWorker())
+ {
+ static instr_time last_report_time;
+ instr_time time_since_last_report;
+
+ Assert(!is_analyze);
+
+ /* Accumulate the delay time. */
+ parallel_vacuum_worker_delay_ns += INSTR_TIME_GET_NANOSEC(delay);
+
+ /* Calculate interval since last report. */
+ INSTR_TIME_SET_ZERO(time_since_last_report);
+ INSTR_TIME_ACCUM_DIFF(time_since_last_report, delay_end, last_report_time);
+
+ /* If we haven't reported in a while, do so now. */
+ if (INSTR_TIME_GET_NANOSEC(time_since_last_report) >=
+ PARALLEL_VACUUM_DELAY_REPORT_INTERVAL_NS)
+ {
+ pgstat_progress_parallel_incr_param(PROGRESS_VACUUM_DELAY_TIME,
+ parallel_vacuum_worker_delay_ns);
+
+ /* Reset variables. */
+ last_report_time = delay_end;
+ parallel_vacuum_worker_delay_ns = 0;
+ }
+ }
+ else if (is_analyze)
+ pgstat_progress_incr_param(PROGRESS_ANALYZE_DELAY_TIME,
+ INSTR_TIME_GET_NANOSEC(delay));
+ else
+ pgstat_progress_incr_param(PROGRESS_VACUUM_DELAY_TIME,
+ INSTR_TIME_GET_NANOSEC(delay));
+ }
+
/*
* We don't want to ignore postmaster death during very long vacuums
* with vacuum_cost_delay configured. We can't use the usual
diff --git a/src/backend/commands/vacuumparallel.c b/src/backend/commands/vacuumparallel.c
index dc3322c256b..2b9d548cdeb 100644
--- a/src/backend/commands/vacuumparallel.c
+++ b/src/backend/commands/vacuumparallel.c
@@ -1094,6 +1094,11 @@ parallel_vacuum_main(dsm_segment *seg, shm_toc *toc)
InstrEndParallelQuery(&buffer_usage[ParallelWorkerNumber],
&wal_usage[ParallelWorkerNumber]);
+ /* Report any remaining cost-based vacuum delay time */
+ if (track_cost_delay_timing)
+ pgstat_progress_parallel_incr_param(PROGRESS_VACUUM_DELAY_TIME,
+ parallel_vacuum_worker_delay_ns);
+
TidStoreDetach(dead_items);
/* Pop the error context stack */
diff --git a/src/backend/utils/misc/guc_tables.c b/src/backend/utils/misc/guc_tables.c
index ce7534d4d23..1efee7af176 100644
--- a/src/backend/utils/misc/guc_tables.c
+++ b/src/backend/utils/misc/guc_tables.c
@@ -1470,6 +1470,15 @@ struct config_bool ConfigureNamesBool[] =
true,
NULL, NULL, NULL
},
+ {
+ {"track_cost_delay_timing", PGC_SUSET, STATS_CUMULATIVE,
+ gettext_noop("Collects timing statistics for cost-based vacuum delay."),
+ NULL
+ },
+ &track_cost_delay_timing,
+ false,
+ NULL, NULL, NULL
+ },
{
{"track_io_timing", PGC_SUSET, STATS_CUMULATIVE,
gettext_noop("Collects timing statistics for database I/O activity."),
diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index c40b7a3121e..6f77e5f8b26 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -632,6 +632,7 @@
#track_activities = on
#track_activity_query_size = 1024 # (change requires restart)
#track_counts = on
+#track_cost_delay_timing = off
#track_io_timing = off
#track_wal_io_timing = off
#track_functions = none # none, pl, all
diff --git a/src/include/commands/progress.h b/src/include/commands/progress.h
index 18e3179ef63..7c736e7b03b 100644
--- a/src/include/commands/progress.h
+++ b/src/include/commands/progress.h
@@ -28,6 +28,7 @@
#define PROGRESS_VACUUM_NUM_DEAD_ITEM_IDS 7
#define PROGRESS_VACUUM_INDEXES_TOTAL 8
#define PROGRESS_VACUUM_INDEXES_PROCESSED 9
+#define PROGRESS_VACUUM_DELAY_TIME 10
/* Phases of vacuum (as advertised via PROGRESS_VACUUM_PHASE) */
#define PROGRESS_VACUUM_PHASE_SCAN_HEAP 1
@@ -46,6 +47,7 @@
#define PROGRESS_ANALYZE_CHILD_TABLES_TOTAL 5
#define PROGRESS_ANALYZE_CHILD_TABLES_DONE 6
#define PROGRESS_ANALYZE_CURRENT_CHILD_TABLE_RELID 7
+#define PROGRESS_ANALYZE_DELAY_TIME 8
/* Phases of analyze (as advertised via PROGRESS_ANALYZE_PHASE) */
#define PROGRESS_ANALYZE_PHASE_ACQUIRE_SAMPLE_ROWS 1
diff --git a/src/include/commands/vacuum.h b/src/include/commands/vacuum.h
index b884304dfe7..b3eedf699af 100644
--- a/src/include/commands/vacuum.h
+++ b/src/include/commands/vacuum.h
@@ -296,6 +296,7 @@ extern PGDLLIMPORT int vacuum_multixact_freeze_min_age;
extern PGDLLIMPORT int vacuum_multixact_freeze_table_age;
extern PGDLLIMPORT int vacuum_failsafe_age;
extern PGDLLIMPORT int vacuum_multixact_failsafe_age;
+extern PGDLLIMPORT bool track_cost_delay_timing;
/*
* Maximum value for default_statistics_target and per-column statistics
@@ -313,6 +314,8 @@ extern PGDLLIMPORT bool VacuumFailsafeActive;
extern PGDLLIMPORT double vacuum_cost_delay;
extern PGDLLIMPORT int vacuum_cost_limit;
+extern PGDLLIMPORT int64 parallel_vacuum_worker_delay_ns;
+
/* in commands/vacuum.c */
extern void ExecVacuum(ParseState *pstate, VacuumStmt *vacstmt, bool isTopLevel);
extern void vacuum(List *relations, VacuumParams *params,
diff --git a/src/test/regress/expected/rules.out b/src/test/regress/expected/rules.out
index 3361f6a69c9..5baba8d39ff 100644
--- a/src/test/regress/expected/rules.out
+++ b/src/test/regress/expected/rules.out
@@ -1932,7 +1932,8 @@ pg_stat_progress_analyze| SELECT s.pid,
s.param5 AS ext_stats_computed,
s.param6 AS child_tables_total,
s.param7 AS child_tables_done,
- (s.param8)::oid AS current_child_table_relid
+ (s.param8)::oid AS current_child_table_relid,
+ ((s.param9)::double precision / (1000000)::double precision) AS delay_time
FROM (pg_stat_get_progress_info('ANALYZE'::text) s(pid, datid, relid, param1, param2, param3, param4, param5, param6, param7, param8, param9, param10, param11, param12, param13, param14, param15, param16, param17, param18, param19, param20)
LEFT JOIN pg_database d ON ((s.datid = d.oid)));
pg_stat_progress_basebackup| SELECT pid,
@@ -2062,7 +2063,8 @@ pg_stat_progress_vacuum| SELECT s.pid,
s.param7 AS dead_tuple_bytes,
s.param8 AS num_dead_item_ids,
s.param9 AS indexes_total,
- s.param10 AS indexes_processed
+ s.param10 AS indexes_processed,
+ ((s.param11)::double precision / (1000000)::double precision) AS delay_time
FROM (pg_stat_get_progress_info('VACUUM'::text) s(pid, datid, relid, param1, param2, param3, param4, param5, param6, param7, param8, param9, param10, param11, param12, param13, param14, param15, param16, param17, param18, param19, param20)
LEFT JOIN pg_database d ON ((s.datid = d.oid)));
pg_stat_recovery_prefetch| SELECT stats_reset,
--
2.34.1
>From e270ddb7e599e22b90b4d6702596770f67569f07 Mon Sep 17 00:00:00 2001
From: Bertrand Drouvot <bertranddrouvot...@gmail.com>
Date: Tue, 11 Feb 2025 07:37:05 +0000
Subject: [PATCH v17 3/3] Add cost-based delay time to VACUUM/ANALYZE (VERBOSE)
This commit adds cost-based delay time to VACUUM/ANALYZE (VERBOSE) and to
autovacuum logs (if track_cost_delay_timing is enabled).
---
doc/src/sgml/config.sgml | 8 +++++---
src/backend/access/heap/vacuumlazy.c | 6 ++++++
src/backend/commands/analyze.c | 6 ++++++
3 files changed, 17 insertions(+), 3 deletions(-)
49.4% doc/src/sgml/
25.2% src/backend/access/heap/
25.3% src/backend/commands/
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 79a66ba7181..15001c01046 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -8261,9 +8261,11 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv;
platforms. You can use the <xref linkend="pgtesttiming"/> tool to
measure the overhead of timing on your system. Cost-based vacuum delay
timing information is displayed in
- <link linkend="vacuum-progress-reporting"><structname>pg_stat_progress_vacuum</structname></link>
- and
- <link linkend="analyze-progress-reporting"><structname>pg_stat_progress_analyze</structname></link>.
+ <link linkend="vacuum-progress-reporting"><structname>pg_stat_progress_vacuum</structname></link>,
+ <link linkend="analyze-progress-reporting"><structname>pg_stat_progress_analyze</structname></link>,
+ in the output of <xref linkend="sql-vacuum"/> when the <literal>VERBOSE</literal>
+ option is used, by autovacuum for auto-vacuums and auto-analyzes,
+ when <xref linkend="guc-log-autovacuum-min-duration"/> is set.
Only superusers and users with the appropriate <literal>SET</literal>
privilege can change this setting.
</para>
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index e4d6d654c0a..735a60b3d9a 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -830,6 +830,12 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
appendStringInfo(&buf, _("I/O timings: read: %.3f ms, write: %.3f ms\n"),
read_ms, write_ms);
}
+ if (track_cost_delay_timing)
+ {
+ double delayed_ms = (double) MyBEEntry->st_progress_param[PROGRESS_VACUUM_DELAY_TIME] / 1000000.0;
+
+ appendStringInfo(&buf, _("delay time: %.3f ms\n"), delayed_ms);
+ }
if (secs_dur > 0 || usecs_dur > 0)
{
read_rate = (double) BLCKSZ * total_blks_read /
diff --git a/src/backend/commands/analyze.c b/src/backend/commands/analyze.c
index e4302f4cdb2..91751d15e66 100644
--- a/src/backend/commands/analyze.c
+++ b/src/backend/commands/analyze.c
@@ -816,6 +816,12 @@ do_analyze_rel(Relation onerel, VacuumParams *params,
appendStringInfo(&buf, _("I/O timings: read: %.3f ms, write: %.3f ms\n"),
read_ms, write_ms);
}
+ if (track_cost_delay_timing)
+ {
+ double delayed_ms = (double) MyBEEntry->st_progress_param[PROGRESS_ANALYZE_DELAY_TIME] / 1000000.0;
+
+ appendStringInfo(&buf, _("delay time: %.3f ms\n"), delayed_ms);
+ }
appendStringInfo(&buf, _("avg read rate: %.3f MB/s, avg write rate: %.3f MB/s\n"),
read_rate, write_rate);
appendStringInfo(&buf, _("buffer usage: %lld hits, %lld reads, %lld dirtied\n"),
--
2.34.1
