Subject: Re: pg_upgrade verbosity when redirecting output to log file

From: Thomas Munro <[email-masked]>
Date: Wed, 16 Feb 2022 17:09:34 +1300

On Tue, Jan 11, 2022 at 4:42 AM Bruce Momjian <[email-masked]> wrote:
> On Sun, Jan  9, 2022 at 10:39:58PM -0800, Andres Freund wrote:
> > On 2022-01-10 01:14:32 -0500, Tom Lane wrote:
> > > I think I'd vote for just nuking that output altogether.
> > > It seems of very dubious value.
> >
> > It seems worthwhile in some form - on large cluster in copy mode, the "Copying
> > user relation files" step can take *quite* a while, and even link/clone mode
> > aren't fast. But perhaps what'd be really needed is something counting up
> > actual progress in percentage of files and/or space...
> >
> > I think just coupling it to verbose mode makes the most sense, for now?
>
> All of this logging is from the stage where I was excited pg_upgrade
> worked, and I wanted to give clear output if it failed in some way ---
> printing the file names seems like an easy solution.  I agree at this
> point that logging should be reduced, and if they want more logging, the
> verbose option is the right way to get it.

+1

---

From: Andres Freund <[email-masked]>
Date: Fri, 18 Feb 2022 17:20:47 -0800

Hi,

> > verbose option is the right way to get it.

I got a bit stuck on how to best resolve this. I felt bad about removing all
interactive progress, because a pg_upgrade can take a while after all. But
it's also not easy to come up with some good, without a substantially bigger
effort than I want to invest.

After all, I just want to be able to read check-world output. Nearly half of
which is pg_upgrade test output right now.

The attached is my attempt at coming up with something halfway sane without
rewriting pg_upgrade logging entirely. I think it mostly ends up with at least
as sane output as the current code. I needed to add a separate
prep_status_progress() function to make that work.

Greetings,

Andres Freund
>From a04d989a64e6c6bc273b0c8c0d778d5f66f00158 Mon Sep 17 00:00:00 2001
From: Andres Freund <[email-masked]>
Date: Fri, 18 Feb 2022 17:16:37 -0800
Subject: [PATCH v2] pg_upgrade: Don't print progress status when output is not
 a tty.

Until this change pg_upgrade with output redirected to a file / pipe would end
up printing all files in the cluster. This has made check-world output
exceedingly verbose.

Author: Andres Freund
Discussion: https://postgr.es/m/CA+hUKGKjrV61ZVJ8OSag+3rKRmCZXPc03bDyWMqhXg3rdZ=[email-masked]
---
 src/bin/pg_upgrade/dump.c        |  2 +-
 src/bin/pg_upgrade/option.c      |  2 +
 src/bin/pg_upgrade/pg_upgrade.c  |  2 +-
 src/bin/pg_upgrade/pg_upgrade.h  |  2 +
 src/bin/pg_upgrade/relfilenode.c |  6 +--
 src/bin/pg_upgrade/util.c        | 63 ++++++++++++++++++++++++++------
 6 files changed, 60 insertions(+), 17 deletions(-)

diff --git a/src/bin/pg_upgrade/dump.c b/src/bin/pg_upgrade/dump.c
index b69b4f95695..29b9e44f782 100644
--- a/src/bin/pg_upgrade/dump.c
+++ b/src/bin/pg_upgrade/dump.c
@@ -29,7 +29,7 @@ generate_old_dump(void)
 			  GLOBALS_DUMP_FILE);
 	check_ok();
 
-	prep_status("Creating dump of database schemas\n");
+	prep_status_progress("Creating dump of database schemas");
 
 	/* create per-db dump files */
 	for (dbnum = 0; dbnum < old_cluster.dbarr.ndbs; dbnum++)
diff --git a/src/bin/pg_upgrade/option.c b/src/bin/pg_upgrade/option.c
index d2c82cc2bbb..e75be2c423e 100644
--- a/src/bin/pg_upgrade/option.c
+++ b/src/bin/pg_upgrade/option.c
@@ -207,6 +207,8 @@ parseCommandLine(int argc, char *argv[])
 	if (log_opts.verbose)
 		pg_log(PG_REPORT, "Running in verbose mode\n");
 
+	log_opts.isatty = isatty(fileno(stdout));
+
 	/* Turn off read-only mode;  add prefix to PGOPTIONS? */
 	if (getenv("PGOPTIONS"))
 	{
diff --git a/src/bin/pg_upgrade/pg_upgrade.c b/src/bin/pg_upgrade/pg_upgrade.c
index f66bbd53079..ecb3e1f6474 100644
--- a/src/bin/pg_upgrade/pg_upgrade.c
+++ b/src/bin/pg_upgrade/pg_upgrade.c
@@ -381,7 +381,7 @@ create_new_objects(void)
 {
 	int			dbnum;
 
-	prep_status("Restoring database schemas in the new cluster\n");
+	prep_status_progress("Restoring database schemas in the new cluster");
 
 	/*
 	 * We cannot process the template1 database concurrently with others,
diff --git a/src/bin/pg_upgrade/pg_upgrade.h b/src/bin/pg_upgrade/pg_upgrade.h
index 0aca0a77aae..ca86c112924 100644
--- a/src/bin/pg_upgrade/pg_upgrade.h
+++ b/src/bin/pg_upgrade/pg_upgrade.h
@@ -274,6 +274,7 @@ typedef struct
 	char	   *basedir;		/* Base output directory */
 	char	   *dumpdir;		/* Dumps */
 	char	   *logdir;			/* Log files */
+	bool		isatty;			/* is stdout a tty */
 } LogOpts;

@@ -427,6 +428,7 @@ void		pg_log(eLogType type, const char *fmt,...) pg_attribute_printf(2, 3);
 void		pg_fatal(const char *fmt,...) pg_attribute_printf(1, 2) pg_attribute_noreturn();
 void		end_progress_output(void);
 void		prep_status(const char *fmt,...) pg_attribute_printf(1, 2);
+void		prep_status_progress(const char *fmt,...) pg_attribute_printf(1, 2);
 void		check_ok(void);
 unsigned int str2uint(const char *str);
 
diff --git a/src/bin/pg_upgrade/relfilenode.c b/src/bin/pg_upgrade/relfilenode.c
index 2f4deb34163..d23ac884bd1 100644
--- a/src/bin/pg_upgrade/relfilenode.c
+++ b/src/bin/pg_upgrade/relfilenode.c
@@ -32,13 +32,13 @@ transfer_all_new_tablespaces(DbInfoArr *old_db_arr, DbInfoArr *new_db_arr,
 	switch (user_opts.transfer_mode)
 	{
 		case TRANSFER_MODE_CLONE:
-			pg_log(PG_REPORT, "Cloning user relation files\n");
+			prep_status_progress("Cloning user relation files");
 			break;
 		case TRANSFER_MODE_COPY:
-			pg_log(PG_REPORT, "Copying user relation files\n");
+			prep_status_progress("Copying user relation files");
 			break;
 		case TRANSFER_MODE_LINK:
-			pg_log(PG_REPORT, "Linking user relation files\n");
+			prep_status_progress("Linking user relation files");
 			break;
 	}
 
diff --git a/src/bin/pg_upgrade/util.c b/src/bin/pg_upgrade/util.c
index d98deb7f24e..6cf02a8ad64 100644
--- a/src/bin/pg_upgrade/util.c
+++ b/src/bin/pg_upgrade/util.c
@@ -38,15 +38,18 @@ report_status(eLogType type, const char *fmt,...)
 }

-/* force blank output for progress display */
 void
 end_progress_output(void)
 {
 	/*
-	 * In case nothing printed; pass a space so gcc doesn't complain about
-	 * empty format string.
+	 * For output to a tty, erase prior contents of progress line. When either
+	 * tty or verbose, indent so that report_status() output will align
+	 * nicely.
 	 */
-	prep_status(" ");
+	if (log_opts.isatty)
+		pg_log(PG_REPORT, "\r%-*s", MESSAGE_WIDTH, "");
+	else if (log_opts.verbose)
+		pg_log(PG_REPORT, "%-*s", MESSAGE_WIDTH, "");
 }

@@ -75,13 +78,42 @@ prep_status(const char *fmt,...)
 	vsnprintf(message, sizeof(message), fmt, args);
 	va_end(args);
 
-	if (strlen(message) > 0 && message[strlen(message) - 1] == '\n')
-		pg_log(PG_REPORT, "%s", message);
-	else
-		/* trim strings that don't end in a newline */
-		pg_log(PG_REPORT, "%-*s", MESSAGE_WIDTH, message);
+	/* trim strings */
+	pg_log(PG_REPORT, "%-*s", MESSAGE_WIDTH, message);
 }
 
+/*
+ * prep_status_progress
+ *
+ *   Like prep_status(), but for potentially longer running operations.
+ *   Details about what item is currently being processed can be displayed
+ *   with pg_log(PG_STATUS, ...). A typical sequence would look like this:
+ *
+ *   prep_status_progress("copying files");
+ *   for (...)
+ *     pg_log(PG_STATUS, "%s", filename);
+ *   end_progress_output();
+ *   report_status(PG_REPORT, "ok");
+ */
+void
+prep_status_progress(const char *fmt,...)
+{
+	va_list		args;
+	char		message[MAX_STRING];
+
+	va_start(args, fmt);
+	vsnprintf(message, sizeof(message), fmt, args);
+	va_end(args);
+
+	/*
+	 * If outputting to a tty / or , append newline. pg_log_v() will put the
+	 * individual progress items onto the next line.
+	 */
+	if (log_opts.isatty || log_opts.verbose)
+		pg_log(PG_REPORT, "%-*s\n", MESSAGE_WIDTH, message);
+	else
+		pg_log(PG_REPORT, "%-*s", MESSAGE_WIDTH, message);
+}
 
 static void
 pg_log_v(eLogType type, const char *fmt, va_list ap)
@@ -111,8 +143,15 @@ pg_log_v(eLogType type, const char *fmt, va_list ap)
 			break;
 
 		case PG_STATUS:
-			/* for output to a display, do leading truncation and append \r */
-			if (isatty(fileno(stdout)))
+			/*
+			 * For output to a display, do leading truncation. Append \r so
+			 * that the next message is output at the start of the line.
+			 *
+			 * If going to non-interactive output, only display progress if
+			 * verbose is enabled. Otherwise the output gets unreasonably
+			 * large by default.
+			 */
+			if (log_opts.isatty)
 				/* -2 because we use a 2-space indent */
 				printf("  %s%-*.*s\r",
 				/* prefix with "..." if we do leading truncation */
@@ -121,7 +160,7 @@ pg_log_v(eLogType type, const char *fmt, va_list ap)
 				/* optional leading truncation */
 					   strlen(message) <= MESSAGE_WIDTH - 2 ? message :
 					   message + strlen(message) - MESSAGE_WIDTH + 3 + 2);
-			else
+			else if (log_opts.verbose)
 				printf("  %s\n", message);
 			break;
 
-- 
2.34.0

---

From: Justin Pryzby <[email-masked]>
Date: Fri, 18 Feb 2022 19:46:26 -0600

I guess the comment should say "or in verbose mode".

-- 
Justin

---

From: Andres Freund <[email-masked]>
Date: Sun, 20 Feb 2022 17:07:25 -0800

Hi,

> I guess the comment should say "or in verbose mode".

Indeed. I think I got caught in a back-and-forth between different
formulations.

Baring that, anybody against committing this?

Greetings,

Andres Freund

---

From: Daniel Gustafsson <[email-masked]>
Date: Mon, 21 Feb 2022 15:29:09 +0100

> On 21 Feb 2022, at 02:07, Andres Freund <[email-masked]> wrote:

> Baring that, anybody against committing this?

LGTM. The above mentioned comment was the only thing I found as well.

--
Daniel Gustafsson		https://vmware.com/

---

From: Andres Freund <[email-masked]>
Date: Mon, 21 Feb 2022 08:35:57 -0800

> LGTM. The above mentioned comment was the only thing I found as well.

Thanks for the review Justin and Daniel. Pushed.