Date: Wed, 21 Jul 2021 08:13:26 -0500
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
Subject: Re: when the startup process doesn't (logging startup delays)
Message-ID: <20210721131326.GA19620@telsasoft.com>
References: <867286.1623073349@sss.pgh.pa.us>
 <CAMm1aWacYkDD5cGyhNYD_nqjD94vxSTPA_1UZdO+Em94POTgyw@mail.gmail.com>
 <20210609161918.GY16435@telsasoft.com>
 <CAMm1aWZNkm0nbVzAsiqnNSpgRT3N0HjT_b30AmjsVLDzjHTgFA@mail.gmail.com>
 <20210610100125.GE16435@telsasoft.com>
 <CAMm1aWbj3G8YJohr+FUOt1R+vz+e5sGiGCoK5kSRCgmDj5k+0Q@mail.gmail.com>
 <20210617125254.GB31772@telsasoft.com>
 <CAMm1aWadG_xgncYxFt-GAqRXWL2WE-5bu3qdJtW6CYEwhw7QbQ@mail.gmail.com>
 <CALj2ACUNaAQjLYnyQvG988d=Qzw5yQhaRLYN6ihaxZShJ6AeHg@mail.gmail.com>
 <CAMm1aWZScAOM4CA60sS90y3qPNtZ75Wo+6mRUry06bVjfRqePg@mail.gmail.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: 
 <CAMm1aWZScAOM4CA60sS90y3qPNtZ75Wo+6mRUry06bVjfRqePg@mail.gmail.com>
User-Agent: Mutt/1.9.4 (2018-02-28)
Archived-At: 
 <https://www.postgresql.org/message-id/20210721131326.GA19620%40telsasoft.com>
Precedence: bulk

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