Thread: pg_upgrade verbosity when redirecting output to log file

pg_upgrade verbosity when redirecting output to log file

From
Andres Freund
Date:
Hi,

I've been annoyed for quite a while that pg_upgrade tests lists all copied
files - it's ~1500 lines or so in the make -C src/bin/pg_ugprade check case
(obviously for a cluster with more objects it's basically unlimited). But
whenever I was looking into something about the issue, I didn't see the log
outpu, leading me to believe somebody else had fixed it (although I thought I
complained about this before, but I couldn't find it in the archives).

Turns out that it only happens when the output is not a tty. And I notice it
whenever I redirect the log output to a file, pipe, or such.


This actually might not be intended?


While util.c:pg_log_v() [1] says

    /* PG_VERBOSE and PG_STATUS are only output in verbose mode */

it actually prints out the status report unconditionally:

...
        case PG_STATUS:
            if (isatty(fileno(stdout)))
                printf("  %s%-*.*s\r",...);
...
            else
                printf("  %s\n", message);
            break;

this isn't bad when stdout is a tty, because the \r will hide the repeated
output. But when its not, we just dump out the progress, regardless of
verbosity.

This code appears to have been this way for a long time and I'm not quite sure
what the intent really is.

It seems not unreasonable to log progress if a tty or if verbose is specified?

I guess there's an argument to be made that outputting all that data
unrequested isn't great in the tty case either. On a cluster with a large
schema that could be quite a few MB of output - enough to slow things down
over a low throughput / high latency link probably.  On a test cluster with
20k tables I had lying around, script -c "pg_upgrade ...." (which simulates a
tty) results in a ~4MB typescript.


A very minor thing is that we do the isatty() thing in every PG_STATUS logging
invocation. Each time that triggers a
ioctl(1, TCGETS, {B38400 opost isig icanon echo ...}) = 0
which isn't a huge cost compared to actually copying a file, but it's not
entirely free either.

Greetings,

Andres Freund


[1] called from
  transfer_all_new_tablespaces() ->
  parallel_transfer_all_new_dbs() ->
  transfer_all_new_dbs() ->
  transfer_single_new_db() ->
  transfer_relfile() ->
        /* Copying files might take some time, so give feedback. */
        pg_log(PG_STATUS, "status: %s", old_file);



Re: pg_upgrade verbosity when redirecting output to log file

From
Andres Freund
Date:
Hi,

On 2022-01-09 20:28:40 -0800, Andres Freund wrote:
> Turns out that it only happens when the output is not a tty. And I notice it
> whenever I redirect the log output to a file, pipe, or such.

Ah. More precisely, it happens when doing
  make -s -Otarget -j32 check-world,
but *not* when
  make -s -Otarget -j32 -C src/bin/pg_upgrade check

because when there's only one target the subprocess ends up with the
FDs make is invoked with, but when there's concurrency -Otarget causes
stdin/out to be temporary files. Leading to the endless output "Copying user
relation files" output when doing check-world...

Greetings,

Andres Freund



Re: pg_upgrade verbosity when redirecting output to log file

From
Tom Lane
Date:
Andres Freund <andres@anarazel.de> writes:
> On 2022-01-09 20:28:40 -0800, Andres Freund wrote:
>> Turns out that it only happens when the output is not a tty. And I notice it
>> whenever I redirect the log output to a file, pipe, or such.

> Ah. More precisely, it happens when doing
>   make -s -Otarget -j32 check-world,
> but *not* when
>   make -s -Otarget -j32 -C src/bin/pg_upgrade check

Fun!  That seems to me to be a strong argument for not letting
the behavior vary depending on isatty().

I think I'd vote for just nuking that output altogether.
It seems of very dubious value.

            regards, tom lane



Re: pg_upgrade verbosity when redirecting output to log file

From
Andres Freund
Date:
Hi,

On 2022-01-10 01:14:32 -0500, Tom Lane wrote:
> Andres Freund <andres@anarazel.de> writes:
> Fun!  That seems to me to be a strong argument for not letting
> the behavior vary depending on isatty().

Yea.


> 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?

Greetings,

Andres Freund



Re: pg_upgrade verbosity when redirecting output to log file

From
Tom Lane
Date:
Andres Freund <andres@anarazel.de> writes:
> On 2022-01-10 01:14:32 -0500, Tom Lane wrote:
>> Andres Freund <andres@anarazel.de> writes:
>> Fun!  That seems to me to be a strong argument for not letting
>> the behavior vary depending on isatty().

> Yea.

> I think just coupling it to verbose mode makes the most sense, for now?

WFM.

            regards, tom lane



Re: pg_upgrade verbosity when redirecting output to log file

From
Bruce Momjian
Date:
On Sun, Jan  9, 2022 at 10:39:58PM -0800, Andres Freund wrote:
> Hi,
> 
> On 2022-01-10 01:14:32 -0500, Tom Lane wrote:
> > Andres Freund <andres@anarazel.de> writes:
> > Fun!  That seems to me to be a strong argument for not letting
> > the behavior vary depending on isatty().
> 
> Yea.
> 
> 
> > 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.

-- 
  Bruce Momjian  <bruce@momjian.us>        https://momjian.us
  EDB                                      https://enterprisedb.com

  If only the physical world exists, free will is an illusion.




Re: pg_upgrade verbosity when redirecting output to log file

From
Thomas Munro
Date:
On Tue, Jan 11, 2022 at 4:42 AM Bruce Momjian <bruce@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



Re: pg_upgrade verbosity when redirecting output to log file

From
Andres Freund
Date:
Hi,

On 2022-02-16 17:09:34 +1300, Thomas Munro wrote:
> On Tue, Jan 11, 2022 at 4:42 AM Bruce Momjian <bruce@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

Attachment

Re: pg_upgrade verbosity when redirecting output to log file

From
Justin Pryzby
Date:
+        * 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)
                                                                                                         
 

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

-- 
Justin



Re: pg_upgrade verbosity when redirecting output to log file

From
Andres Freund
Date:
Hi,

On 2022-02-18 19:46:26 -0600, Justin Pryzby wrote:
> +        * 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)
>
> 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



Re: pg_upgrade verbosity when redirecting output to log file

From
Daniel Gustafsson
Date:
> On 21 Feb 2022, at 02:07, Andres Freund <andres@anarazel.de> 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/




Re: pg_upgrade verbosity when redirecting output to log file

From
Andres Freund
Date:
On 2022-02-21 15:29:09 +0100, Daniel Gustafsson wrote:
> > On 21 Feb 2022, at 02:07, Andres Freund <andres@anarazel.de> wrote:
> 
> > Baring that, anybody against committing this?
> 
> LGTM. The above mentioned comment was the only thing I found as well.

Thanks for the review Justin and Daniel. Pushed.