On Fri, Jan 24, 2025 at 02:19:59PM -0600, Sami Imseih wrote: > So currently, the report of the last_(autoanalyze|analyze)_time > is set before the index_vacuum_cleanup, but for logging purposes > the elapsed time is calculated afterwards. Most users will not notice > this, but I think that is wrong as well. > > I think we should calculate endtime and elapsedtime and call > pgstat_report_analyze after the index_vacuum_cleanup; and > before vac_close_indexes. This is more accurate and will > avoid incurring the extra GetCurrentTimestamp() call. > > What do you think?
I think that this is hiding a behavior change while adding new counters, and both changes are independent. Another thing that is slightly incorrect to do if we take the argument of only adding the counters is moving around the call of pgstat_progress_end_command(), because it's not really wrong as-is, either. I'd suggest to make all that a separate discussion. The addition of the extra GetCurrentTimestamp() in the report path does not stress me much, FWIW, and keeping the tracking of the end time within the report routines for [auto]analyze and [auto]vacuum has the merit that the caller does not need to worry about more TimestampDifferenceMilliseconds() calculations. I have put my hands on this patch, and at the end I think that we should just do the attached, which is simpler and addresses your use-case. Note also that the end time is acquired while the entries are not locked in the report routines, and some tweaks in the docs and comments. -- Michael
From 456325d581a1a28b49e82de48172b19fca8b204a Mon Sep 17 00:00:00 2001 From: Michael Paquier <mich...@paquier.xyz> Date: Mon, 27 Jan 2025 09:23:55 +0900 Subject: [PATCH v7] Track per relation cumulative time spent in [auto]vacuum and [auto]analyze This commit adds four fields to the statistics of relations, aggregating the amount of time spent for each operation on a relation: - total_vacuum_time, for manual vacuum. - total_autovacuum_time, for autovacuum. - total_analyze_time, for manual analyze. - total_autoanalyze_time, for autoanalyze. This gives users the option to derive the average time spent for these operations with the help of the related "count" fields. XXX: catversion bump XXX: stats version bump Author: Sami Imseih Reviewed-by: Bertrand Drouvot, Michael Paquier Discussion: https://www.postgresql.org/message-id/CAA5RZ0uVOGBYmPEeGF2d1B_67tgNjKx_bKDuL%2BoUftuoz%2B%3DY1g%40mail.gmail.com --- src/include/catalog/pg_proc.dat | 16 +++++++++ src/include/pgstat.h | 10 ++++-- src/backend/access/heap/vacuumlazy.c | 7 ++-- src/backend/catalog/system_views.sql | 6 +++- src/backend/commands/analyze.c | 12 ++++--- src/backend/utils/activity/pgstat_relation.c | 21 ++++++++--- src/backend/utils/adt/pgstatfuncs.c | 28 +++++++++++++++ src/test/regress/expected/rules.out | 18 ++++++++-- doc/src/sgml/monitoring.sgml | 38 ++++++++++++++++++++ 9 files changed, 139 insertions(+), 17 deletions(-) diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat index 2aafdbc3e93..5b8c2ad2a54 100644 --- a/src/include/catalog/pg_proc.dat +++ b/src/include/catalog/pg_proc.dat @@ -5543,6 +5543,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 => 'float8', 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 => 'float8', 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 => 'float8', 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 => 'float8', 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 d0d45150977..ea6889d7090 100644 --- a/src/include/pgstat.h +++ b/src/include/pgstat.h @@ -465,6 +465,11 @@ typedef struct PgStat_StatTabEntry PgStat_Counter analyze_count; TimestampTz last_autoanalyze_time; /* autovacuum initiated */ PgStat_Counter autoanalyze_count; + + PgStat_Counter total_vacuum_time; /* times in milliseconds */ + PgStat_Counter total_autovacuum_time; + PgStat_Counter total_analyze_time; + PgStat_Counter total_autoanalyze_time; } PgStat_StatTabEntry; typedef struct PgStat_WalStats @@ -649,10 +654,11 @@ 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); extern void pgstat_report_analyze(Relation rel, PgStat_Counter livetuples, PgStat_Counter deadtuples, - bool resetcounter); + bool resetcounter, TimestampTz starttime); /* * If stats are enabled, but pending data hasn't been prepared yet, call diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c index 5b0e790e121..5ed43e43914 100644 --- a/src/backend/access/heap/vacuumlazy.c +++ b/src/backend/access/heap/vacuumlazy.c @@ -386,7 +386,6 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, if (instrument) { pg_rusage_init(&ru0); - starttime = GetCurrentTimestamp(); if (track_io_timing) { startreadtime = pgStatBlockReadTime; @@ -394,6 +393,9 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, } } + /* Used for instrumentation and stats report */ + starttime = GetCurrentTimestamp(); + pgstat_progress_start_command(PROGRESS_COMMAND_VACUUM, RelationGetRelid(rel)); @@ -659,7 +661,8 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, rel->rd_rel->relisshared, Max(vacrel->new_live_tuples, 0), vacrel->recently_dead_tuples + - vacrel->missed_dead_tuples); + vacrel->missed_dead_tuples, + starttime); pgstat_progress_end_command(); if (instrument) diff --git a/src/backend/catalog/system_views.sql b/src/backend/catalog/system_views.sql index 46868bf7e89..cddc3ea9b53 100644 --- a/src/backend/catalog/system_views.sql +++ b/src/backend/catalog/system_views.sql @@ -696,7 +696,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 2a7769b1fd1..f8da32e9aef 100644 --- a/src/backend/commands/analyze.c +++ b/src/backend/commands/analyze.c @@ -344,8 +344,8 @@ do_analyze_rel(Relation onerel, VacuumParams *params, RestrictSearchPath(); /* - * measure elapsed time if called with verbose or if autovacuum logging - * requires it + * When verbose or autovacuum logging is used, initialize a resource usage + * snapshot and optionally track I/O timing. */ if (instrument) { @@ -356,9 +356,11 @@ do_analyze_rel(Relation onerel, VacuumParams *params, } pg_rusage_init(&ru0); - starttime = GetCurrentTimestamp(); } + /* Used for instrumentation and stats report */ + starttime = GetCurrentTimestamp(); + /* * Determine which columns to analyze * @@ -693,9 +695,9 @@ do_analyze_rel(Relation onerel, VacuumParams *params, */ if (!inh) pgstat_report_analyze(onerel, totalrows, totaldeadrows, - (va_cols == NIL)); + (va_cols == NIL), starttime); 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); /* * If this isn't part of VACUUM ANALYZE, let index AMs do cleanup. diff --git a/src/backend/utils/activity/pgstat_relation.c b/src/backend/utils/activity/pgstat_relation.c index 965a7fe2c64..d64595a165c 100644 --- a/src/backend/utils/activity/pgstat_relation.c +++ b/src/backend/utils/activity/pgstat_relation.c @@ -208,19 +208,22 @@ 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) { PgStat_EntryRef *entry_ref; PgStatShared_Relation *shtabentry; PgStat_StatTabEntry *tabentry; Oid dboid = (shared ? InvalidOid : MyDatabaseId); TimestampTz ts; + PgStat_Counter elapsedtime; if (!pgstat_track_counts) return; /* Store the data in the table's hash table entry. */ ts = GetCurrentTimestamp(); + elapsedtime = TimestampDifferenceMilliseconds(starttime, ts); /* block acquiring lock for the same reason as pgstat_report_autovac() */ entry_ref = pgstat_get_entry_ref_locked(PGSTAT_KIND_RELATION, @@ -248,11 +251,13 @@ pgstat_report_vacuum(Oid tableoid, bool shared, { tabentry->last_autovacuum_time = ts; tabentry->autovacuum_count++; + tabentry->total_autovacuum_time += elapsedtime; } else { tabentry->last_vacuum_time = ts; tabentry->vacuum_count++; + tabentry->total_vacuum_time += elapsedtime; } pgstat_unlock_entry(entry_ref); @@ -276,12 +281,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) { PgStat_EntryRef *entry_ref; PgStatShared_Relation *shtabentry; PgStat_StatTabEntry *tabentry; Oid dboid = (rel->rd_rel->relisshared ? InvalidOid : MyDatabaseId); + TimestampTz ts; + PgStat_Counter elapsedtime; if (!pgstat_track_counts) return; @@ -315,6 +322,10 @@ pgstat_report_analyze(Relation rel, deadtuples = Max(deadtuples, 0); } + /* Store the data in the table's hash table entry. */ + ts = GetCurrentTimestamp(); + elapsedtime = TimestampDifferenceMilliseconds(starttime, ts); + /* block acquiring lock for the same reason as pgstat_report_autovac() */ entry_ref = pgstat_get_entry_ref_locked(PGSTAT_KIND_RELATION, dboid, RelationGetRelid(rel), @@ -338,13 +349,15 @@ pgstat_report_analyze(Relation rel, if (AmAutoVacuumWorkerProcess()) { - tabentry->last_autoanalyze_time = GetCurrentTimestamp(); + tabentry->last_autoanalyze_time = ts; tabentry->autoanalyze_count++; + tabentry->total_autoanalyze_time += elapsedtime; } else { - tabentry->last_analyze_time = GetCurrentTimestamp(); + tabentry->last_analyze_time = ts; tabentry->analyze_count++; + tabentry->total_analyze_time += elapsedtime; } pgstat_unlock_entry(entry_ref); diff --git a/src/backend/utils/adt/pgstatfuncs.c b/src/backend/utils/adt/pgstatfuncs.c index 0f5e0a9778d..e9096a88492 100644 --- a/src/backend/utils/adt/pgstatfuncs.c +++ b/src/backend/utils/adt/pgstatfuncs.c @@ -106,6 +106,34 @@ PG_STAT_GET_RELENTRY_INT64(tuples_updated) /* pg_stat_get_vacuum_count */ PG_STAT_GET_RELENTRY_INT64(vacuum_count) +#define PG_STAT_GET_RELENTRY_FLOAT8(stat) \ +Datum \ +CppConcat(pg_stat_get_,stat)(PG_FUNCTION_ARGS) \ +{ \ + Oid relid = PG_GETARG_OID(0); \ + double result; \ + PgStat_StatTabEntry *tabentry; \ + \ + if ((tabentry = pgstat_fetch_stat_tabentry(relid)) == NULL) \ + result = 0; \ + else \ + result = (double) (tabentry->stat); \ + \ + PG_RETURN_FLOAT8(result); \ +} + +/* pg_stat_get_total_vacuum_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_vacuum_time) + +/* pg_stat_get_total_autovacuum_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_autovacuum_time) + +/* pg_stat_get_total_analyze_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_analyze_time) + +/* pg_stat_get_total_autoanalyze_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_autoanalyze_time) + #define PG_STAT_GET_RELENTRY_TIMESTAMPTZ(stat) \ Datum \ CppConcat(pg_stat_get_,stat)(PG_FUNCTION_ARGS) \ diff --git a/src/test/regress/expected/rules.out b/src/test/regress/expected/rules.out index 856a8349c50..3361f6a69c9 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))) @@ -2190,7 +2194,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, @@ -2238,7 +2246,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, diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml index e5888fae2b5..0bdb51eedb9 100644 --- a/doc/src/sgml/monitoring.sgml +++ b/doc/src/sgml/monitoring.sgml @@ -4053,6 +4053,44 @@ description | Waiting for a newly initialized WAL file to reach durable storage daemon </para></entry> </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>total_vacuum_time</structfield> <type>double precision</type> + </para> + <para> + Total time this table has been vacuumed, in milliseconds + </para></entry> + </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>total_autovacuum_time</structfield> <type>double precision</type> + </para> + <para> + Total time this table has been vacuumed by the autovacuum daemon, + in milliseconds + </para></entry> + </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>total_analyze_time</structfield> <type>double precision</type> + </para> + <para> + Total time this table has been analyzed, in milliseconds + </para></entry> + </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>total_autoanalyze_time</structfield> <type>double precision</type> + </para> + <para> + Total time this table has been analyzed by the autovacuum daemon, + in milliseconds + </para></entry> + </row> </tbody> </tgroup> </table> -- 2.47.2
signature.asc
Description: PGP signature
