Print opening INFO lines with coulours

By default it use inverse printing for lines:

  INFO: vacuuming tablename
  INFO: repacking tablename
  INFO: analyzing tablename

It helps with orientation inside verbose output of REINDEX, VACUUM and ANALYZE commands.

Author: okbob@github.com

src/backend/access/heap/vacuumlazy.c

@@ -1005,6 +1005,7 @@ heap_vacuum_rel(Relation rel, const VacuumParams *params,
 			WalUsage	walusage;
 			BufferUsage bufferusage;
 			StringInfoData buf;
+			StringInfoData detail;
 			char	   *msgfmt;
 			int32		diff;
 			double		read_rate = 0,
@@ -1034,7 +1035,7 @@ heap_vacuum_rel(Relation rel, const VacuumParams *params,
 				 * VACUUM VERBOSE ereport
 				 */
 				Assert(!params->is_wraparound);
-				msgfmt = _("finished vacuuming \"%s.%s.%s\": index scans: %d\n");
+				msgfmt = _("finished vacuuming \"%s.%s.%s\"");
 			}
 			else if (params->is_wraparound)
 			{
@@ -1045,69 +1046,73 @@ heap_vacuum_rel(Relation rel, const VacuumParams *params,
 				 * case all the same, just in case.
 				 */
 				if (vacrel->aggressive)
-					msgfmt = _("automatic aggressive vacuum to prevent wraparound of table \"%s.%s.%s\": index scans: %d\n");
+					msgfmt = _("automatic aggressive vacuum to prevent wraparound of table \"%s.%s.%s\"");
 				else
-					msgfmt = _("automatic vacuum to prevent wraparound of table \"%s.%s.%s\": index scans: %d\n");
+					msgfmt = _("automatic vacuum to prevent wraparound of table \"%s.%s.%s\"");
 			}
 			else
 			{
 				if (vacrel->aggressive)
-					msgfmt = _("automatic aggressive vacuum of table \"%s.%s.%s\": index scans: %d\n");
+					msgfmt = _("automatic aggressive vacuum of table \"%s.%s.%s\"\n");
 				else
-					msgfmt = _("automatic vacuum of table \"%s.%s.%s\": index scans: %d\n");
+					msgfmt = _("automatic vacuum of table \"%s.%s.%s\"");
 			}
 			appendStringInfo(&buf, msgfmt,
 							 vacrel->dbname,
 							 vacrel->relnamespace,
-							 vacrel->relname,
-							 vacrel->num_index_scans);
-			appendStringInfo(&buf, _("pages: %u removed, %u remain, %u scanned (%.2f%% of total), %u eagerly scanned\n"),
+							 vacrel->relname);
+
+			initStringInfo(&detail);
+
+			appendStringInfo(&detail, "index scans: %d\n", vacrel->num_index_scans);
+
+			appendStringInfo(&detail, _("pages: %u removed, %u remain, %u scanned (%.2f%% of total), %u eagerly scanned\n"),
 							 vacrel->removed_pages,
 							 new_rel_pages,
 							 vacrel->scanned_pages,
 							 orig_rel_pages == 0 ? 100.0 :
 							 100.0 * vacrel->scanned_pages /
 							 orig_rel_pages,
 							 vacrel->eager_scanned_pages);
-			appendStringInfo(&buf,
+			appendStringInfo(&detail,
 							 _("tuples: %" PRId64 " removed, %" PRId64 " remain, %" PRId64 " are dead but not yet removable\n"),
 							 vacrel->tuples_deleted,
 							 (int64) vacrel->new_rel_tuples,
 							 vacrel->recently_dead_tuples);
 			if (vacrel->missed_dead_tuples > 0)
-				appendStringInfo(&buf,
+				appendStringInfo(&detail,
 								 _("tuples missed: %" PRId64 " dead from %u pages not removed due to cleanup lock contention\n"),
 								 vacrel->missed_dead_tuples,
 								 vacrel->missed_dead_pages);
 			diff = (int32) (ReadNextTransactionId() -
 							vacrel->cutoffs.OldestXmin);
-			appendStringInfo(&buf,
+			appendStringInfo(&detail,
 							 _("removable cutoff: %u, which was %d XIDs old when operation ended\n"),
 							 vacrel->cutoffs.OldestXmin, diff);
 			if (frozenxid_updated)
 			{
 				diff = (int32) (vacrel->NewRelfrozenXid -
 								vacrel->cutoffs.relfrozenxid);
-				appendStringInfo(&buf,
+				appendStringInfo(&detail,
 								 _("new relfrozenxid: %u, which is %d XIDs ahead of previous value\n"),
 								 vacrel->NewRelfrozenXid, diff);
 			}
 			if (minmulti_updated)
 			{
 				diff = (int32) (vacrel->NewRelminMxid -
 								vacrel->cutoffs.relminmxid);
-				appendStringInfo(&buf,
+				appendStringInfo(&detail,
 								 _("new relminmxid: %u, which is %d MXIDs ahead of previous value\n"),
 								 vacrel->NewRelminMxid, diff);
 			}
-			appendStringInfo(&buf, _("frozen: %u pages from table (%.2f%% of total) had %" PRId64 " tuples frozen\n"),
+			appendStringInfo(&detail, _("frozen: %u pages from table (%.2f%% of total) had %" PRId64 " tuples frozen\n"),
 							 vacrel->new_frozen_tuple_pages,
 							 orig_rel_pages == 0 ? 100.0 :
 							 100.0 * vacrel->new_frozen_tuple_pages /
 							 orig_rel_pages,
 							 vacrel->tuples_frozen);
 
-			appendStringInfo(&buf,
+			appendStringInfo(&detail,
 							 _("visibility map: %u pages set all-visible, %u pages set all-frozen (%u were all-visible)\n"),
 							 vacrel->new_all_visible_pages,
 							 vacrel->new_all_visible_all_frozen_pages +
@@ -1116,35 +1121,35 @@ heap_vacuum_rel(Relation rel, const VacuumParams *params,
 			if (vacrel->do_index_vacuuming)
 			{
 				if (vacrel->nindexes == 0 || vacrel->num_index_scans == 0)
-					appendStringInfoString(&buf, _("index scan not needed: "));
+					appendStringInfoString(&detail, _("index scan not needed: "));
 				else
-					appendStringInfoString(&buf, _("index scan needed: "));
+					appendStringInfoString(&detail, _("index scan needed: "));
 
 				msgfmt = _("%u pages from table (%.2f%% of total) had %" PRId64 " dead item identifiers removed\n");
 			}
 			else
 			{
 				if (!VacuumFailsafeActive)
-					appendStringInfoString(&buf, _("index scan bypassed: "));
+					appendStringInfoString(&detail, _("index scan bypassed: "));
 				else
-					appendStringInfoString(&buf, _("index scan bypassed by failsafe: "));
+					appendStringInfoString(&detail, _("index scan bypassed by failsafe: "));
 
 				msgfmt = _("%u pages from table (%.2f%% of total) have %" PRId64 " dead item identifiers\n");
 			}
-			appendStringInfo(&buf, msgfmt,
+			appendStringInfo(&detail, msgfmt,
 							 vacrel->lpdead_item_pages,
 							 orig_rel_pages == 0 ? 100.0 :
 							 100.0 * vacrel->lpdead_item_pages / orig_rel_pages,
 							 vacrel->lpdead_items);
 
 			if (vacrel->worker_usage.vacuum.nplanned > 0)
-				appendStringInfo(&buf,
+				appendStringInfo(&detail,
 								 _("parallel workers: index vacuum: %d planned, %d launched in total\n"),
 								 vacrel->worker_usage.vacuum.nplanned,
 								 vacrel->worker_usage.vacuum.nlaunched);
 
 			if (vacrel->worker_usage.cleanup.nplanned > 0)
-				appendStringInfo(&buf,
+				appendStringInfo(&detail,
 								 _("parallel workers: index cleanup: %d planned, %d launched\n"),
 								 vacrel->worker_usage.cleanup.nplanned,
 								 vacrel->worker_usage.cleanup.nlaunched);
@@ -1156,7 +1161,7 @@ heap_vacuum_rel(Relation rel, const VacuumParams *params,
 				if (!istat)
 					continue;
 
-				appendStringInfo(&buf,
+				appendStringInfo(&detail,
 								 _("index \"%s\": pages: %u in total, %u newly deleted, %u currently deleted, %u reusable\n"),
 								 indnames[i],
 								 istat->num_pages,
@@ -1172,15 +1177,15 @@ heap_vacuum_rel(Relation rel, const VacuumParams *params,
 				 * above call to pgstat_progress_end_command() to not clear
 				 * the st_progress_param array.
 				 */
-				appendStringInfo(&buf, _("delay time: %.3f ms\n"),
+				appendStringInfo(&detail, _("delay time: %.3f ms\n"),
 								 (double) MyBEEntry->st_progress_param[PROGRESS_VACUUM_DELAY_TIME] / 1000000.0);
 			}
 			if (track_io_timing)
 			{
 				double		read_ms = (double) (pgStatBlockReadTime - startreadtime) / 1000;
 				double		write_ms = (double) (pgStatBlockWriteTime - startwritetime) / 1000;
 
-				appendStringInfo(&buf, _("I/O timings: read: %.3f ms, write: %.3f ms\n"),
+				appendStringInfo(&detail, _("I/O timings: read: %.3f ms, write: %.3f ms\n"),
 								 read_ms, write_ms);
 			}
 			if (secs_dur > 0 || usecs_dur > 0)
@@ -1190,14 +1195,14 @@ heap_vacuum_rel(Relation rel, const VacuumParams *params,
 				write_rate = (double) BLCKSZ * total_blks_dirtied /
 					(1024 * 1024) / (secs_dur + usecs_dur / 1000000.0);
 			}
-			appendStringInfo(&buf, _("avg read rate: %.3f MB/s, avg write rate: %.3f MB/s\n"),
+			appendStringInfo(&detail, _("avg read rate: %.3f MB/s, avg write rate: %.3f MB/s\n"),
 							 read_rate, write_rate);
-			appendStringInfo(&buf,
+			appendStringInfo(&detail,
 							 _("buffer usage: %" PRId64 " hits, %" PRId64 " reads, %" PRId64 " dirtied\n"),
 							 total_blks_hit,
 							 total_blks_read,
 							 total_blks_dirtied);
-			appendStringInfo(&buf,
+			appendStringInfo(&detail,
 							 _("WAL usage: %" PRId64 " records, %" PRId64 " full page images, %" PRIu64 " bytes, %" PRIu64 " full page image bytes, %" PRId64 " buffers full\n"),
 							 walusage.wal_records,
 							 walusage.wal_fpi,
@@ -1213,17 +1218,18 @@ heap_vacuum_rel(Relation rel, const VacuumParams *params,
 			 * one dead items are collected, even if index vacuuming is
 			 * disabled.
 			 */
-			appendStringInfo(&buf,
+			appendStringInfo(&detail,
 							 ngettext("memory usage: dead item storage %.2f MB accumulated across %d reset (limit %.2f MB each)\n",
 									  "memory usage: dead item storage %.2f MB accumulated across %d resets (limit %.2f MB each)\n",
 									  vacrel->num_dead_items_resets),
 							 (double) vacrel->total_dead_items_bytes / (1024 * 1024),
 							 vacrel->num_dead_items_resets,
 							 (double) dead_items_max_bytes / (1024 * 1024));
-			appendStringInfo(&buf, _("system usage: %s"), pg_rusage_show(&ru0));
+			appendStringInfo(&detail, _("system usage: %s"), pg_rusage_show(&ru0));
 
 			ereport(verbose ? INFO : LOG,
-					(errmsg_internal("%s", buf.data)));
+					(errmsg_internal("%s", buf.data),
+					 errdetail_internal("%s", detail.data)));
 			pfree(buf.data);
 		}
 	}

src/common/logging.c

@@ -32,11 +32,13 @@ static const char *sgr_error = NULL;
 static const char *sgr_warning = NULL;
 static const char *sgr_note = NULL;
 static const char *sgr_locus = NULL;
+static const char *sgr_info = NULL;
 
 #define SGR_ERROR_DEFAULT "01;31"
 #define SGR_WARNING_DEFAULT "01;35"
 #define SGR_NOTE_DEFAULT "01;36"
 #define SGR_LOCUS_DEFAULT "01"
+#define SGR_INFO_DEFAULT "07"
 
 #define ANSI_ESCAPE_FMT "\x1b[%sm"
 #define ANSI_ESCAPE_RESET "\x1b[0m"
@@ -145,6 +147,8 @@ pg_logging_init(const char *argv0)
 							sgr_note = strdup(value);
 						if (strcmp(name, "locus") == 0)
 							sgr_locus = strdup(value);
+						if (strcmp(name, "info") == 0)
+							sgr_info = strdup(value);
 					}
 				}
 
@@ -157,6 +161,7 @@ pg_logging_init(const char *argv0)
 			sgr_warning = SGR_WARNING_DEFAULT;
 			sgr_note = SGR_NOTE_DEFAULT;
 			sgr_locus = SGR_LOCUS_DEFAULT;
+			sgr_info = SGR_INFO_DEFAULT;
 		}
 	}
 }
@@ -353,7 +358,28 @@ pg_log_generic_v(enum pg_log_level level, enum pg_log_part part,
 	if (required_len >= 2 && buf[required_len - 2] == '\n')
 		buf[required_len - 2] = '\0';
 
-	fprintf(stderr, "%s\n", buf);
+	if (level == PG_LOG_INFO && sgr_info)
+	{
+		if (strncmp(buf, "INFO: ", strlen("INFO: ")) == 0)
+		{
+			char *firstnl = strchr(buf, '\n');
+			if (firstnl)
+			{
+				*firstnl = '\0';
+			}
+
+			fprintf(stderr, ANSI_ESCAPE_FMT, sgr_info);
+			fprintf(stderr, "%s\n", buf);
+			fprintf(stderr, ANSI_ESCAPE_RESET);
+
+			if (firstnl)
+				fprintf(stderr, "%s\n", firstnl + 1);
+		}
+		else
+			fprintf(stderr, "%s\n", buf);
+	}
+	else
+		fprintf(stderr, "%s\n", buf);
 	if (log_logfile)
 	{
 		fprintf(log_logfile, "%s\n", buf);