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

Justin Pryzby <pryzby@telsasoft.com>

From: Justin Pryzby <pryzby@telsasoft.com>
To: Nitin Jadhav <nitinjadhavpostgres@gmail.com>
Cc: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>, Tom Lane <tgl@sss.pgh.pa.us>, Robert Haas <robertmhaas@gmail.com>, 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
Date: 2021-07-21T13:13:26Z
Lists: pgsql-hackers
I think walkdir() should only call LogStartupProgress(FSYNC_IN_PROGRESS, path);
when action == datadir_fsync_fname.

ResetUnloggedRelations() is calling
ResetUnloggedRelationsInTablespaceDir("base", op);
before calling InitStartupProgress().

This shows StartupXLOG() calling ResetUnloggedRelations() twice.
Should they both be shown ?  If so, maybe they should be distinguished as here:

        elog(DEBUG1, "resetting unlogged relations: cleanup %d init %d",
                 (op & UNLOGGED_RELATION_CLEANUP) != 0,
                 (op & UNLOGGED_RELATION_INIT) != 0);

On Wed, Jul 21, 2021 at 12:52:24PM +0530, Nitin Jadhav wrote:
> 2021-07-20 18:47:32.046 IST [102230] LOG:  listening on IPv4 address "127.0.0.1", port 5445
> 2021-07-20 18:47:32.048 IST [102230] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5445"
> 2021-07-20 18:47:32.051 IST [102234] LOG:  database system was interrupted; last known up at 2021-07-20 18:46:27 IST
> 2021-07-20 18:47:32.060 IST [102234] LOG:  data directory sync (fsync) complete after 0.00 s
> 2021-07-20 18:47:32.060 IST [102234] LOG:  database system was not properly shut down; automatic recovery in progress
> 2021-07-20 18:47:32.063 IST [102234] LOG:  unlogged relations reset after 0.00 s
> 2021-07-20 18:47:32.063 IST [102234] LOG:  redo starts at 0/14EF418
> 2021-07-20 18:47:33.063 IST [102234] LOG:  redo in progress, elapsed time: 1.00 s, current LSN: 0/5C13D28
> 2021-07-20 18:47:34.063 IST [102234] LOG:  redo in progress, elapsed time: 2.00 s, current LSN: 0/A289160
> 2021-07-20 18:47:35.063 IST [102234] LOG:  redo in progress, elapsed time: 3.00 s, current LSN: 0/EE2DE10
> 2021-07-20 18:47:35.563 IST [102234] LOG:  invalid record length at 0/115C63E0: wanted 24, got 0
> 2021-07-20 18:47:35.563 IST [102234] LOG:  redo done at 0/115C63B8 system usage: CPU: user: 3.58 s, system: 0.14 s, elapsed: 3.50 s
> 2021-07-20 18:47:35.564 IST [102234] LOG:  unlogged relations reset after 0.00 s
> 2021-07-20 18:47:35.706 IST [102230] LOG:  database system is ready to accept connections

-- 
Justin



Commits

  1. Un-revert "Disable STARTUP_PROGRESS_TIMEOUT in standby mode."

  2. Revert "Disable STARTUP_PROGRESS_TIMEOUT in standby mode."

  3. Disable STARTUP_PROGRESS_TIMEOUT in standby mode.

  4. Fix race condition in startup progress reporting.

  5. Report progress of startup operations that take a long time.

  6. Add enable_timeout_every() to fire the same timeout repeatedly.