Reorder log_autovacuum_min_duration log output.

This order seems more natural.  It starts with details that are
particular to heap and index data structures, and ends with system-level
costs incurred during the autovacuum worker's VACUUM/ANALYZE operation.

Author: Peter Geoghegan <pg@bowt.ie>
Discussion: https://postgr.es/m/CAH2-WzkzxK6ahA9xxsOftRtBX_R0swuHZsvo4QUbak1Bz7hb7Q@mail.gmail.com
Backpatch: 14-, which enhanced the log output in various ways.

diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index fe2e6d021f4bff4af3260bc14dcea38870f89ae4..cf120a27cfc667a7e914e193a4f084e93cc1ac91 100644 (file)
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -739,6 +739,7 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
                {
                        StringInfoData buf;
                        char       *msgfmt;
+                       BlockNumber orig_rel_pages;
 
                        TimestampDifference(starttime, endtime, &secs, &usecs);
 
@@ -796,34 +797,27 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
                                                         (long long) vacrel->new_rel_tuples,
                                                         (long long) vacrel->new_dead_tuples,
                                                         OldestXmin);
-                       appendStringInfo(&buf,
-                                                        _("buffer usage: %lld hits, %lld misses, %lld dirtied\n"),
-                                                        (long long) VacuumPageHit,
-                                                        (long long) VacuumPageMiss,
-                                                        (long long) VacuumPageDirty);
-                       if (vacrel->rel_pages > 0)
+                       orig_rel_pages = vacrel->rel_pages + vacrel->pages_removed;
+                       if (orig_rel_pages > 0)
                        {
-                               BlockNumber orig_rel_pages;
-
                                if (vacrel->do_index_vacuuming)
                                {
-                                       msgfmt = _("%u pages from table (%.2f%% of total) had %lld dead item identifiers removed\n");
-
                                        if (vacrel->nindexes == 0 || vacrel->num_index_scans == 0)
                                                appendStringInfoString(&buf, _("index scan not needed: "));
                                        else
                                                appendStringInfoString(&buf, _("index scan needed: "));
+
+                                       msgfmt = _("%u pages from table (%.2f%% of total) had %lld dead item identifiers removed\n");
                                }
                                else
                                {
-                                       msgfmt = _("%u pages from table (%.2f%% of total) have %lld dead item identifiers\n");
-
                                        if (!vacrel->failsafe_active)
                                                appendStringInfoString(&buf, _("index scan bypassed: "));
                                        else
                                                appendStringInfoString(&buf, _("index scan bypassed by failsafe: "));
+
+                                       msgfmt = _("%u pages from table (%.2f%% of total) have %lld dead item identifiers\n");
                                }
-                               orig_rel_pages = vacrel->rel_pages + vacrel->pages_removed;
                                appendStringInfo(&buf, msgfmt,
                                                                 vacrel->lpdead_item_pages,
                                                                 100.0 * vacrel->lpdead_item_pages / orig_rel_pages,
@@ -844,8 +838,6 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
                                                                 istat->pages_deleted,
                                                                 istat->pages_free);
                        }
-                       appendStringInfo(&buf, _("avg read rate: %.3f MB/s, avg write rate: %.3f MB/s\n"),
-                                                        read_rate, write_rate);
                        if (track_io_timing)
                        {
                                appendStringInfoString(&buf, _("I/O timings:"));
@@ -859,12 +851,19 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
                                                                         (double) (pgStatBlockWriteTime - startwritetime) / 1000);
                                appendStringInfoChar(&buf, '\n');
                        }
-                       appendStringInfo(&buf, _("system usage: %s\n"), pg_rusage_show(&ru0));
+                       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 misses, %lld dirtied\n"),
+                                                        (long long) VacuumPageHit,
+                                                        (long long) VacuumPageMiss,
+                                                        (long long) VacuumPageDirty);
                        appendStringInfo(&buf,
-                                                        _("WAL usage: %lld records, %lld full page images, %llu bytes"),
+                                                        _("WAL usage: %lld records, %lld full page images, %llu bytes\n"),
                                                         (long long) walusage.wal_records,
                                                         (long long) walusage.wal_fpi,
                                                         (unsigned long long) walusage.wal_bytes);
+                       appendStringInfo(&buf, _("system usage: %s"), pg_rusage_show(&ru0));
 
                        ereport(LOG,
                                        (errmsg_internal("%s", buf.data)));

diff --git a/src/backend/commands/analyze.c b/src/backend/commands/analyze.c
index 8d7b38d1707ac84e8e9d9ac2a47802998621fff2..a17349bcd6c8d6a522a09dc5dfd31d14356d9bcf 100644 (file)
--- a/src/backend/commands/analyze.c
+++ b/src/backend/commands/analyze.c
@@ -777,12 +777,6 @@ do_analyze_rel(Relation onerel, VacuumParams *params,
                                                         get_database_name(MyDatabaseId),
                                                         get_namespace_name(RelationGetNamespace(onerel)),
                                                         RelationGetRelationName(onerel));
-                       appendStringInfo(&buf, _("buffer usage: %lld hits, %lld misses, %lld dirtied\n"),
-                                                        (long long) AnalyzePageHit,
-                                                        (long long) AnalyzePageMiss,
-                                                        (long long) AnalyzePageDirty);
-                       appendStringInfo(&buf, _("avg read rate: %.3f MB/s, avg write rate: %.3f MB/s\n"),
-                                                        read_rate, write_rate);
                        if (track_io_timing)
                        {
                                appendStringInfoString(&buf, _("I/O timings:"));
@@ -796,6 +790,12 @@ do_analyze_rel(Relation onerel, VacuumParams *params,
                                                                         (double) (pgStatBlockWriteTime - startwritetime) / 1000);
                                appendStringInfoChar(&buf, '\n');
                        }
+                       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 misses, %lld dirtied\n"),
+                                                        (long long) AnalyzePageHit,
+                                                        (long long) AnalyzePageMiss,
+                                                        (long long) AnalyzePageDirty);
                        appendStringInfo(&buf, _("system usage: %s"), pg_rusage_show(&ru0));
 
                        ereport(LOG,