Re: when the startup process doesn't (logging startup delays)
Nitin Jadhav <nitinjadhavpostgres@gmail.com>
From: Nitin Jadhav <nitinjadhavpostgres@gmail.com>
To: Robert Haas <robertmhaas@gmail.com>
Cc: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>, Justin Pryzby <pryzby@telsasoft.com>, Tom Lane <tgl@sss.pgh.pa.us>, Andres Freund <andres@anarazel.de>, Stephen Frost <sfrost@snowman.net>, Magnus Hagander <magnus@hagander.net>, Thomas Munro <thomas.munro@gmail.com>, "pgsql-hackers@postgresql.org" <pgsql-hackers@postgresql.org>
Date: 2021-07-29T08:56:53Z
Lists: pgsql-hackers
Attachments
- v8-startup-process-progress.patch (application/x-patch) patch v8
> The InitPostgres() case occurs when the server is started in bootstrap > mode (during initdb) or in single-user mode (postgres --single). I do > not see any reason why we shouldn't produce progress messages in at > least the latter case. I suspect that someone who is in the rather > desperate scenario of having to use single-user mode would really like > to know how long the server is going to take to start up. Thanks for sharing the information. I have done the necessary changes to show the logs during the latter case (postgres --single) and verified the log messages. > +1 to emit the same log messages in single-user mode and basically > whoever calls StartupXLOG. Do we need to adjust the GUC parameter > log_startup_progress_interval(a reasonable value) so that the logs are > generated by default? At present, this feature is enabled by default and the initial value set for log_startup_progress_interval is 10 seconds. On Wed, Jul 28, 2021 at 9:07 PM Robert Haas <robertmhaas@gmail.com> wrote: > > On Wed, Jul 28, 2021 at 11:25 AM Bharath Rupireddy > <bharath.rupireddyforpostgres@gmail.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
Commits
-
Un-revert "Disable STARTUP_PROGRESS_TIMEOUT in standby mode."
- ecb01e6ebb5a 15.3 landed
-
Revert "Disable STARTUP_PROGRESS_TIMEOUT in standby mode."
- 1eadfbdd7eb0 15.2 landed
-
Disable STARTUP_PROGRESS_TIMEOUT in standby mode.
- 98e7234242a6 15.2 landed
- 8a2f783cc489 16.0 landed
-
Fix race condition in startup progress reporting.
- 5ccceb2946d4 15.0 landed
-
Report progress of startup operations that take a long time.
- 9ce346eabf35 15.0 landed
-
Add enable_timeout_every() to fire the same timeout repeatedly.
- 732e6677a667 15.0 landed