public inbox for [email protected]
help / color / mirror / Atom feedFrom: Sami Imseih <[email protected]>
To: pgsql-hackers <[email protected]>
Subject: POC: track vacuum/analyze cumulative time per relation
Date: Thu, 2 Jan 2025 12:24:06 -0600
Message-ID: <CAA5RZ0uVOGBYmPEeGF2d1B_67tgNjKx_bKDuL+oUftuoz+=Y1g@mail.gmail.com> (raw)
Hi,
After a recent question regarding tracking vacuum start_time in
pg_stat_all_tables [1], it dawned on me that this view is missing
an important cumulative metric, which is how much time is spent
performing vacuum per table.
Currently, the only way a user can get this
information is if they enable autovacuum logging or track timing
for manual vacuums. Even then, if a user wants to trend
the time spent vacuuming over time, they must store the
timing data somewhere and perform the calculations.
Also, unless autovacuum logging is enabled for all a/v
operations, they could have gaps in their analysis.
Having the total (auto)vacuum elapsed time
along side the existing (auto)vaccum_count
allows a user to track the average time an
operating overtime and to find vacuum tuning
opportunities.
The same can also be said for (auto)analyze.
attached a patch ( without doc changes)
that adds 4 new columns:
total_autovacuum_time
total_vacuum_time
total_autoanalyze_time
total_analyze_time
Below is an example of output and how it
can be used to derive the average vacuum
operation time.
postgres=# select
relname,
autovacuum_count,
total_autovacuum_time,
total_autovacuum_time/NULLIF(autovacuum_count,0) average_autovac_time,
vacuum_count,
total_vacuum_time,
total_vacuum_time/NULLIF(vacuum_count,0) average_vac_time
from pg_catalog.pg_stat_all_tables
where relname = 'pgbench_history';
-[ RECORD 1 ]---------+-----------------
relname | pgbench_history
autovacuum_count | 3
total_autovacuum_time | 1689
average_autovac_time | 563
vacuum_count | 1
total_vacuum_time | 1
average_vac_time | 1
It should be noted that the timing is only tracked
when the vacuum or analyze operation completes,
as is the case with the other metrics.
Also, there is another discussion in-flight [2] regarding
tracking vacuum run history in a view, but this serves a
different purpose as this will provide all the metrics
that are other wise exposed in vacuum logging
via sql. This history will also be required to drop
entries using some criteria to keep the cache from
growing infinitely.
Feedback for the attached patch is appreciated!
Regards,
Sami Imseih
Amazon Web Services (AWS)
[1] https://www.postgresql.org/message-id/flat/CAGjGUAKQ4UBNdkjunH2qLsdUVG-3F9gCuG0Kb0hToo%2BuMmSteQ%40m...
[2] https://www.postgresql.org/message-id/flat/b68ab452-c41f-4d04-893f-eaab84f1855b%40vondra.me
Attachments:
[application/octet-stream] POC-track-vacuum-analyze-cumulative-time-per-table.patch (13.2K, ../CAA5RZ0uVOGBYmPEeGF2d1B_67tgNjKx_bKDuL+oUftuoz+=Y1g@mail.gmail.com/2-POC-track-vacuum-analyze-cumulative-time-per-table.patch)
download | inline diff:
From 0c549b8ba716a6dda51b0ab22bd01fdbb89f7187 Mon Sep 17 00:00:00 2001
From: Sami Imseih <[email protected]>
Date: Thu, 2 Jan 2025 12:19:23 -0600
Subject: [PATCH 1/1] POC: track vacuum/analyze cumulative time per table
---
src/backend/access/heap/vacuumlazy.c | 10 +++++---
src/backend/catalog/system_views.sql | 6 ++++-
src/backend/commands/analyze.c | 11 +++++----
src/backend/utils/activity/pgstat_relation.c | 26 ++++++++++++++------
src/backend/utils/adt/pgstatfuncs.c | 12 +++++++++
src/include/catalog/pg_proc.dat | 16 ++++++++++++
src/include/pgstat.h | 11 +++++++--
src/test/regress/expected/rules.out | 18 +++++++++++---
8 files changed, 87 insertions(+), 23 deletions(-)
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 09fab08b8e..a3b21c26ff 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -319,6 +319,7 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
new_rel_allvisible;
PGRUsage ru0;
TimestampTz starttime = 0;
+ TimestampTz endtime = 0;
PgStat_Counter startreadtime = 0,
startwritetime = 0;
WalUsage startwalusage = pgWalUsage;
@@ -329,10 +330,10 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
verbose = (params->options & VACOPT_VERBOSE) != 0;
instrument = (verbose || (AmAutoVacuumWorkerProcess() &&
params->log_min_duration >= 0));
+ starttime = GetCurrentTimestamp();
if (instrument)
{
pg_rusage_init(&ru0);
- starttime = GetCurrentTimestamp();
if (track_io_timing)
{
startreadtime = pgStatBlockReadTime;
@@ -601,17 +602,18 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
* soon in cases where the failsafe prevented significant amounts of heap
* vacuuming.
*/
+ endtime = GetCurrentTimestamp();
pgstat_report_vacuum(RelationGetRelid(rel),
rel->rd_rel->relisshared,
Max(vacrel->new_live_tuples, 0),
vacrel->recently_dead_tuples +
- vacrel->missed_dead_tuples);
+ vacrel->missed_dead_tuples,
+ starttime,
+ endtime);
pgstat_progress_end_command();
if (instrument)
{
- TimestampTz endtime = GetCurrentTimestamp();
-
if (verbose || params->log_min_duration == 0 ||
TimestampDifferenceExceeds(starttime, endtime,
params->log_min_duration))
diff --git a/src/backend/catalog/system_views.sql b/src/backend/catalog/system_views.sql
index 7a595c84db..cf35bff30b 100644
--- a/src/backend/catalog/system_views.sql
+++ b/src/backend/catalog/system_views.sql
@@ -691,7 +691,11 @@ CREATE VIEW pg_stat_all_tables AS
pg_stat_get_vacuum_count(C.oid) AS vacuum_count,
pg_stat_get_autovacuum_count(C.oid) AS autovacuum_count,
pg_stat_get_analyze_count(C.oid) AS analyze_count,
- pg_stat_get_autoanalyze_count(C.oid) AS autoanalyze_count
+ pg_stat_get_autoanalyze_count(C.oid) AS autoanalyze_count,
+ pg_stat_get_total_vacuum_time(C.oid) AS total_vacuum_time,
+ 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
FROM pg_class C LEFT JOIN
pg_index I ON C.oid = I.indrelid
LEFT JOIN pg_namespace N ON (N.oid = C.relnamespace)
diff --git a/src/backend/commands/analyze.c b/src/backend/commands/analyze.c
index 2a7769b1fd..9da9f3f791 100644
--- a/src/backend/commands/analyze.c
+++ b/src/backend/commands/analyze.c
@@ -299,6 +299,7 @@ do_analyze_rel(Relation onerel, VacuumParams *params,
HeapTuple *rows;
PGRUsage ru0;
TimestampTz starttime = 0;
+ TimestampTz endtime = 0;
MemoryContext caller_context;
Oid save_userid;
int save_sec_context;
@@ -356,8 +357,8 @@ do_analyze_rel(Relation onerel, VacuumParams *params,
}
pg_rusage_init(&ru0);
- starttime = GetCurrentTimestamp();
}
+ starttime = GetCurrentTimestamp();
/*
* Determine which columns to analyze
@@ -682,6 +683,8 @@ do_analyze_rel(Relation onerel, VacuumParams *params,
in_outer_xact);
}
+ endtime = GetCurrentTimestamp();
+
/*
* Now report ANALYZE to the cumulative stats system. For regular tables,
* we do it only if not doing inherited stats. For partitioned tables, we
@@ -693,9 +696,9 @@ do_analyze_rel(Relation onerel, VacuumParams *params,
*/
if (!inh)
pgstat_report_analyze(onerel, totalrows, totaldeadrows,
- (va_cols == NIL));
+ (va_cols == NIL), starttime, endtime);
else if (onerel->rd_rel->relkind == RELKIND_PARTITIONED_TABLE)
- pgstat_report_analyze(onerel, 0, 0, (va_cols == NIL));
+ pgstat_report_analyze(onerel, 0, 0, (va_cols == NIL), starttime, endtime);
/*
* If this isn't part of VACUUM ANALYZE, let index AMs do cleanup.
@@ -732,8 +735,6 @@ do_analyze_rel(Relation onerel, VacuumParams *params,
/* Log the action if appropriate */
if (instrument)
{
- TimestampTz endtime = GetCurrentTimestamp();
-
if (verbose || params->log_min_duration == 0 ||
TimestampDifferenceExceeds(starttime, endtime,
params->log_min_duration))
diff --git a/src/backend/utils/activity/pgstat_relation.c b/src/backend/utils/activity/pgstat_relation.c
index 2cc304f881..6e4d5bea37 100644
--- a/src/backend/utils/activity/pgstat_relation.c
+++ b/src/backend/utils/activity/pgstat_relation.c
@@ -208,20 +208,18 @@ pgstat_drop_relation(Relation rel)
*/
void
pgstat_report_vacuum(Oid tableoid, bool shared,
- PgStat_Counter livetuples, PgStat_Counter deadtuples)
+ PgStat_Counter livetuples, PgStat_Counter deadtuples,
+ TimestampTz starttime, TimestampTz endtime)
{
PgStat_EntryRef *entry_ref;
PgStatShared_Relation *shtabentry;
PgStat_StatTabEntry *tabentry;
Oid dboid = (shared ? InvalidOid : MyDatabaseId);
- TimestampTz ts;
+ long elapsedtime = TimestampDifferenceMilliseconds(starttime, endtime);
if (!pgstat_track_counts)
return;
- /* Store the data in the table's hash table entry. */
- ts = GetCurrentTimestamp();
-
/* block acquiring lock for the same reason as pgstat_report_autovac() */
entry_ref = pgstat_get_entry_ref_locked(PGSTAT_KIND_RELATION,
dboid, tableoid, false);
@@ -246,15 +244,20 @@ pgstat_report_vacuum(Oid tableoid, bool shared,
if (AmAutoVacuumWorkerProcess())
{
- tabentry->last_autovacuum_time = ts;
+ tabentry->last_autovacuum_time = endtime;
tabentry->autovacuum_count++;
}
else
{
- tabentry->last_vacuum_time = ts;
+ tabentry->last_vacuum_time = endtime;
tabentry->vacuum_count++;
}
+ if (AmAutoVacuumWorkerProcess())
+ tabentry->total_autovacuum_time += elapsedtime;
+ else
+ tabentry->total_vacuum_time += elapsedtime;
+
pgstat_unlock_entry(entry_ref);
/*
@@ -276,12 +279,14 @@ pgstat_report_vacuum(Oid tableoid, bool shared,
void
pgstat_report_analyze(Relation rel,
PgStat_Counter livetuples, PgStat_Counter deadtuples,
- bool resetcounter)
+ bool resetcounter, TimestampTz starttime,
+ TimestampTz endtime)
{
PgStat_EntryRef *entry_ref;
PgStatShared_Relation *shtabentry;
PgStat_StatTabEntry *tabentry;
Oid dboid = (rel->rd_rel->relisshared ? InvalidOid : MyDatabaseId);
+ long elapsedtime = TimestampDifferenceMilliseconds(starttime, endtime);
if (!pgstat_track_counts)
return;
@@ -347,6 +352,11 @@ pgstat_report_analyze(Relation rel,
tabentry->analyze_count++;
}
+ if (AmAutoVacuumWorkerProcess())
+ tabentry->total_autoanalyze_time += elapsedtime;
+ else
+ tabentry->total_analyze_time += elapsedtime;
+
pgstat_unlock_entry(entry_ref);
/* see pgstat_report_vacuum() */
diff --git a/src/backend/utils/adt/pgstatfuncs.c b/src/backend/utils/adt/pgstatfuncs.c
index 3245f3a8d8..161857dcb1 100644
--- a/src/backend/utils/adt/pgstatfuncs.c
+++ b/src/backend/utils/adt/pgstatfuncs.c
@@ -106,6 +106,18 @@ PG_STAT_GET_RELENTRY_INT64(tuples_updated)
/* pg_stat_get_vacuum_count */
PG_STAT_GET_RELENTRY_INT64(vacuum_count)
+/* pg_stat_get_vacuum_time */
+PG_STAT_GET_RELENTRY_INT64(total_vacuum_time)
+
+/* pg_stat_get_autovacuum_time */
+PG_STAT_GET_RELENTRY_INT64(total_autovacuum_time)
+
+/* pg_stat_get_analyze_time */
+PG_STAT_GET_RELENTRY_INT64(total_analyze_time)
+
+/* pg_stat_get_autoanalyze_time */
+PG_STAT_GET_RELENTRY_INT64(total_autoanalyze_time)
+
#define PG_STAT_GET_RELENTRY_TIMESTAMPTZ(stat) \
Datum \
CppConcat(pg_stat_get_,stat)(PG_FUNCTION_ARGS) \
diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat
index b37e8a6f88..6ea09d4bcb 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -5540,6 +5540,22 @@
proname => 'pg_stat_get_autoanalyze_count', provolatile => 's',
proparallel => 'r', prorettype => 'int8', proargtypes => 'oid',
prosrc => 'pg_stat_get_autoanalyze_count' },
+{ oid => '8406', descr => 'total vacuum time, in milliseconds',
+ proname => 'pg_stat_get_total_vacuum_time', provolatile => 's',
+ proparallel => 'r', prorettype => 'int8', proargtypes => 'oid',
+ prosrc => 'pg_stat_get_total_vacuum_time' },
+{ oid => '8407', descr => 'total autovacuum time, in milliseconds',
+ proname => 'pg_stat_get_total_autovacuum_time', provolatile => 's',
+ proparallel => 'r', prorettype => 'int8', proargtypes => 'oid',
+ prosrc => 'pg_stat_get_total_autovacuum_time' },
+{ oid => '8408', descr => 'total analyze time, in milliseconds',
+ proname => 'pg_stat_get_total_analyze_time', provolatile => 's',
+ proparallel => 'r', prorettype => 'int8', proargtypes => 'oid',
+ prosrc => 'pg_stat_get_total_analyze_time' },
+{ oid => '8409', descr => 'total autoanalyze time, in milliseconds',
+ proname => 'pg_stat_get_total_autoanalyze_time', provolatile => 's',
+ proparallel => 'r', prorettype => 'int8', proargtypes => 'oid',
+ prosrc => 'pg_stat_get_total_autoanalyze_time' },
{ oid => '1936', descr => 'statistics: currently active backend IDs',
proname => 'pg_stat_get_backend_idset', prorows => '100', proretset => 't',
provolatile => 's', proparallel => 'r', prorettype => 'int4',
diff --git a/src/include/pgstat.h b/src/include/pgstat.h
index 0d8427f27d..d6a2a0e367 100644
--- a/src/include/pgstat.h
+++ b/src/include/pgstat.h
@@ -493,6 +493,11 @@ typedef struct PgStat_StatTabEntry
PgStat_Counter analyze_count;
TimestampTz last_autoanalyze_time; /* autovacuum initiated */
PgStat_Counter autoanalyze_count;
+
+ PgStat_Counter total_vacuum_time; /* user initiated vacuum */
+ PgStat_Counter total_autovacuum_time; /* autovacuum initiated */
+ PgStat_Counter total_analyze_time; /* user initiated vacuum */
+ PgStat_Counter total_autoanalyze_time; /* autovacuum initiated */
} PgStat_StatTabEntry;
typedef struct PgStat_WalStats
@@ -667,10 +672,12 @@ extern void pgstat_assoc_relation(Relation rel);
extern void pgstat_unlink_relation(Relation rel);
extern void pgstat_report_vacuum(Oid tableoid, bool shared,
- PgStat_Counter livetuples, PgStat_Counter deadtuples);
+ PgStat_Counter livetuples, PgStat_Counter deadtuples,
+ TimestampTz starttime, TimestampTz endtime);
extern void pgstat_report_analyze(Relation rel,
PgStat_Counter livetuples, PgStat_Counter deadtuples,
- bool resetcounter);
+ bool resetcounter, TimestampTz starttime,
+ TimestampTz endtime);
/*
* If stats are enabled, but pending data hasn't been prepared yet, call
diff --git a/src/test/regress/expected/rules.out b/src/test/regress/expected/rules.out
index 3014d047fe..33f631dafa 100644
--- a/src/test/regress/expected/rules.out
+++ b/src/test/regress/expected/rules.out
@@ -1804,7 +1804,11 @@ pg_stat_all_tables| SELECT c.oid AS relid,
pg_stat_get_vacuum_count(c.oid) AS vacuum_count,
pg_stat_get_autovacuum_count(c.oid) AS autovacuum_count,
pg_stat_get_analyze_count(c.oid) AS analyze_count,
- pg_stat_get_autoanalyze_count(c.oid) AS autoanalyze_count
+ pg_stat_get_autoanalyze_count(c.oid) AS autoanalyze_count,
+ pg_stat_get_total_vacuum_time(c.oid) AS total_vacuum_time,
+ 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
FROM ((pg_class c
LEFT JOIN pg_index i ON ((c.oid = i.indrelid)))
LEFT JOIN pg_namespace n ON ((n.oid = c.relnamespace)))
@@ -2188,7 +2192,11 @@ pg_stat_sys_tables| SELECT relid,
vacuum_count,
autovacuum_count,
analyze_count,
- autoanalyze_count
+ autoanalyze_count,
+ total_vacuum_time,
+ total_autovacuum_time,
+ total_analyze_time,
+ total_autoanalyze_time
FROM pg_stat_all_tables
WHERE ((schemaname = ANY (ARRAY['pg_catalog'::name, 'information_schema'::name])) OR (schemaname ~ '^pg_toast'::text));
pg_stat_user_functions| SELECT p.oid AS funcid,
@@ -2236,7 +2244,11 @@ pg_stat_user_tables| SELECT relid,
vacuum_count,
autovacuum_count,
analyze_count,
- autoanalyze_count
+ autoanalyze_count,
+ total_vacuum_time,
+ total_autovacuum_time,
+ total_analyze_time,
+ total_autoanalyze_time
FROM pg_stat_all_tables
WHERE ((schemaname <> ALL (ARRAY['pg_catalog'::name, 'information_schema'::name])) AND (schemaname !~ '^pg_toast'::text));
pg_stat_wal| SELECT wal_records,
--
2.39.5 (Apple Git-154)
view thread (2+ messages)
reply
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: [email protected]
Cc: [email protected]
Subject: Re: POC: track vacuum/analyze cumulative time per relation
In-Reply-To: <CAA5RZ0uVOGBYmPEeGF2d1B_67tgNjKx_bKDuL+oUftuoz+=Y1g@mail.gmail.com>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox