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]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); 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);
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
Attachments:
v2-0001-pg_upgrade-Don-t-print-progress-status-when-outpu.patchtext/x-diff; charset=us-asciiDownload+60-18
+ * 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.