pg_upgrade verbosity when redirecting output to log file

From: Andres Freund <andres(at)anarazel(dot)de>
To: pgsql-hackers(at)postgresql(dot)org, Bruce Momjian <bruce(at)momjian(dot)us>
Subject: pg_upgrade verbosity when redirecting output to log file
Date: 2022-01-10 04:28:40
Message-ID: 20220110042840.qvg47z4uegqmce5l@alap3.anarazel.de
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-hackers

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);

Responses

Browse pgsql-hackers by date

  From Date Subject
Next Message Andres Freund 2022-01-10 04:36:25 Re: pg_upgrade verbosity when redirecting output to log file
Previous Message Amul Sul 2022-01-10 04:16:23 Re: TAP test to cover "EndOfLogTLI != replayTLI" case