Thread: pg_upgrade verbosity when redirecting output to log file
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);
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
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
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
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
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.
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
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
+ * 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
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
> 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/
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.