Re: when the startup process doesn't (logging startup delays)

On Wed, Jul 28, 2021 at 11:25 AM Bharath Rupireddy
<bharath(dot)rupireddyforpostgres(at)gmail(dot)com> wrote:
> > Perhaps during initdb we don't want messages, but I'm not sure that we
> > need to do anything about that here. None of the messages that the
> > server normally produces show up when you run initdb, so I guess they
> > are getting redirected to /dev/null or something.
>
> I enabled the below log message in XLogFlush and ran initdb, it is
> printing these logs onto the stdout, looks like the logs have not been
> redirected to /dev/null in initdb/bootstrap mode.
>
> #ifdef WAL_DEBUG
> if (XLOG_DEBUG)
> elog(LOG, "xlog flush request %X/%X; write %X/%X; flush %X/%X",
> LSN_FORMAT_ARGS(record),
> LSN_FORMAT_ARGS(LogwrtResult.Write),
> LSN_FORMAT_ARGS(LogwrtResult.Flush));
> #endif
>
> So, even in bootstrap mode, can we use the above #ifdef WAL_DEBUG and
> XLOG_DEBUG to print those logs? It looks like the problem with these
> macros is that they are not settable by normal users in the production
> environment, but only by the developers. I'm not sure how much it is
> helpful to print the startup process progress logs in bootstrap mode.
> Maybe we can use the IsBootstrapProcessingMode macro to disable these
> logs in the bootstrap mode.

I don't think we should drag XLOG_DEBUG into this. That's a debugging
facility that isn't really relevant to the topic at hand. The point is
the server normally prints a bunch of messages that we don't see in
bootstrap mode. For example:

[rhaas pgsql]$ postgres
2021-07-28 11:32:33.824 EDT [36801] LOG: starting PostgreSQL 15devel
on x86_64-apple-darwin19.6.0, compiled by clang version 5.0.2
(tags/RELEASE_502/final), 64-bit
2021-07-28 11:32:33.825 EDT [36801] LOG: listening on IPv6 address
"::1", port 5432
2021-07-28 11:32:33.825 EDT [36801] LOG: listening on IPv4 address
"127.0.0.1", port 5432
2021-07-28 11:32:33.826 EDT [36801] LOG: listening on Unix socket
"/tmp/.s.PGSQL.5432"
2021-07-28 11:32:33.846 EDT [36802] LOG: database system was shut
down at 2021-07-28 11:32:32 EDT
2021-07-28 11:32:33.857 EDT [36801] LOG: database system is ready to
accept connections

None of that shows up when you run initdb. Taking a fast look at the
code, I don't think the reasons are the same for all of those
messages. Some of the code isn't reached, whereas e.g. "database
system was shut down at 2021-07-28 11:32:32 EDT" is special-cased. I'm
not sure right off the top of my head what this code should do, but
ideally it looks something like one of the cases we've already got.

--
Robert Haas
EDB: http://www.enterprisedb.com