Hi, On 2022-02-16 17:09:34 +1300, Thomas Munro wrote: > On Tue, Jan 11, 2022 at 4:42 AM Bruce Momjian <br...@momjian.us> 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
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 <and...@anarazel.de> 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=f...@mail.gmail.com --- 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
