Track per-relation cumulative time spent in [auto]vacuum and [auto]analyze
authorMichael Paquier <michael@paquier.xyz>
Tue, 28 Jan 2025 00:57:32 +0000 (09:57 +0900)
committerMichael Paquier <michael@paquier.xyz>
Tue, 28 Jan 2025 00:57:32 +0000 (09:57 +0900)
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 vacuum done by the autovacuum daemon.
- total_analyze_time, for manual analyze.
- total_autoanalyze_time, for analyze done by the autovacuum daemon.

This gives users the option to derive the average time spent for these
operations with the help of the related "count" fields.

Bump catalog version (for the catalog changes) and PGSTAT_FILE_FORMAT_ID
(for the additions in PgStat_StatTabEntry).

Author: Sami Imseih
Reviewed-by: Bertrand Drouvot, Michael Paquier
Discussion: https://postgr.es/m/CAA5RZ0uVOGBYmPEeGF2d1B_67tgNjKx_bKDuL+oUftuoz+=Y1g@mail.gmail.com

doc/src/sgml/monitoring.sgml
src/backend/access/heap/vacuumlazy.c
src/backend/catalog/system_views.sql
src/backend/commands/analyze.c
src/backend/utils/activity/pgstat_relation.c
src/backend/utils/adt/pgstatfuncs.c
src/include/catalog/catversion.h
src/include/catalog/pg_proc.dat
src/include/pgstat.h
src/test/regress/expected/rules.out

index e5888fae2b52fa733820cdad7a2a24df412dd13d..4e917f159aa684c079e7c83cdcf130cb02255d09 100644 (file)
@@ -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 manually 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 manually 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>
index 5b0e790e121df39bb7e4847a7e7198984705c3e6..5ed43e43914c445a1e5ab3c2a9617c15c7d673a5 100644 (file)
@@ -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)
index 46868bf7e89123d92fcd6e52c2b2cbaf49a72b3b..cddc3ea9b530e0a826fb06d10586926505add413 100644 (file)
@@ -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)
index 2a7769b1fd1fac49b3fa0db3575a0af371c1836e..f8da32e9aef73db8ff7fcfcb608547a791fe13c1 100644 (file)
@@ -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.
index 965a7fe2c649fdc1099a9226d45d01107c18d398..d64595a165cc2085fb1abf8732034d1cb29a732e 100644 (file)
@@ -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);
index 0f5e0a9778dc8a94be86bbcd717986591afba610..e9096a88492c68f4cef22424c3c166bae2b2668a 100644 (file)
@@ -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)                 \
index e3a308024de3a3302cedbf6e71a5bac412b9761b..21b3029a1515767c48d4b2930023b91cb47e920a 100644 (file)
@@ -57,6 +57,6 @@
  */
 
 /*                         yyyymmddN */
-#define CATALOG_VERSION_NO 202501232
+#define CATALOG_VERSION_NO 202501281
 
 #endif
index 2aafdbc3e9365e908e817dd362e72b2aca0e2145..5b8c2ad2a54291ae2ccf3f22284764aef902719b 100644 (file)
   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',
index d0d4515097740bd91626e24b4282a7f98432737c..81ec0161c0936d0db1f9d691bf237dfaff0ae61a 100644 (file)
@@ -212,7 +212,7 @@ typedef struct PgStat_TableXactStatus
  * ------------------------------------------------------------
  */
 
-#define PGSTAT_FILE_FORMAT_ID  0x01A5BCB1
+#define PGSTAT_FILE_FORMAT_ID  0x01A5BCB2
 
 typedef struct PgStat_ArchiverStats
 {
@@ -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
index 856a8349c50536a2c4bd813a5f34516b1fd0bf23..3361f6a69c92797eb1f59f2a03fcfbc0afa17301 100644 (file)
@@ -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,