Date: Tue, 7 Sep 2021 06:49:03 -0500
From: Justin Pryzby <pryzby@telsasoft.com>
To: Nitin Jadhav <nitinjadhavpostgres@gmail.com>
Cc: Michael Paquier <michael@paquier.xyz>,
	Robert Haas <robertmhaas@gmail.com>,
	Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.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>,
	Pg Hackers <pgsql-hackers@postgresql.org>
Subject: Re: when the startup process doesn't (logging startup delays)
Message-ID: <20210907114903.GJ26465@telsasoft.com>
References: <20210725175654.GA23997@telsasoft.com>
 <CA+TgmoY-0AUppRhiOGg1Bev+CwE_ZTajCDAY8B-wSLuw0KGC0w@mail.gmail.com>
 <20210726153023.GC23997@telsasoft.com>
 <20210814214700.GO10479@telsasoft.com>
 <CA+TgmoZtbqxaOLdpNkBcDbz=41tWALA8kpH4M=RWtPYHC7-KNg@mail.gmail.com>
 <CAMm1aWZrnYp1WocvoXcR2W2CGuqhgO+UjA9yz29kT6j1Axe=-w@mail.gmail.com>
 <CAMm1aWY6E+S2Q93yqvWGukZZ1SDR1tjEr_UAjeVFCqvqiQqseg@mail.gmail.com>
 <20210904022327.GE26465@telsasoft.com>
 <YTb4cDKWaAKfoTMM@paquier.xyz>
 <CAMm1aWbV6_7d3-J0RLKWMysB4fdjgTN_0zynav9Fi+tKepe2Hw@mail.gmail.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: 
 <CAMm1aWbV6_7d3-J0RLKWMysB4fdjgTN_0zynav9Fi+tKepe2Hw@mail.gmail.com>
User-Agent: Mutt/1.9.4 (2018-02-28)
Archived-At: 
 <https://www.postgresql.org/message-id/20210907114903.GJ26465%40telsasoft.com>
Precedence: bulk

On Tue, Sep 07, 2021 at 03:07:15PM +0530, Nitin Jadhav wrote:
> > Looking over this version, I realized something I (or you) should have
> > noticed sooner: you've added the RegisterTimeout call to
> > InitPostgres(), but that's for things that are used by all backends,
> > and this is only used by the startup process. So it seems to me that
> > the right place is StartupProcessMain. That would have the further
> > advantage of allowing startup_progress_timeout_handler to be made
> > static. begin_startup_progress_phase() and
> > startup_progress_timeout_has_expired() are the actual API functions
> > though so they will need to remain extern.
> >
> > I agree with Robert that a standby server should not continuously show timing
> > messages for WAL replay.
> 
> The earlier discussion wrt this point is as follows.

I think you're confusing discussions.

Robert was talking about initdb/bootstrap/single, and I separately and
independently asked about hot standbys.  It seems like Robert and I agreed
about the desired behavior and there was no further discussion.

> > Honestly, I don't see why we should have
> > a GUC for what's proposed here.  A value too low would bloat the logs
> > with entries that are not that meaningful.  A value too large would
> > just prevent access to some information wanted.  Wouldn't it be better
> > to just pick up a value like 10s or 20s?

I don't think bloating logs is a issue for values > 10sec.

You agreed that it's important to choose the "right" value, but I think that
will vary between users.  Some installations with large checkpoint_timeout
might anticipate taking 15+min to perform recovery, but others might even have
a strict requirement that recovery must not take more than (say) 10sec; someone
might want to use this to verify that, or to optimize the slow parts of
recovery, with an interval that someone else might not care about.

> > +       {"log_startup_progress_interval", PGC_SIGHUP, LOGGING_WHEN,
> > +           gettext_noop("Sets the time interval between each progress update "
> > +                        "of the startup process."),
> > +           gettext_noop("0 logs all messages. -1 turns this feature off."),
> > +           GUC_UNIT_MS,
|+               10, -1, INT_MAX,
> > The unit is incorrect here, as that would default to 10ms, contrary to
> > what the documentation says about 10s.
> 
> Kindly refer the previous few discussions wrt this point.

You copied and pasted unrelated emails, which isn't helpful.

Michael is right.  You updated some of the units based on Robert's suggestion
to use MS, but didn't update all of the corresponding parts of the patch.
guc.c says that the units are in MS, which means that unqualified values are
interpretted as such.  But postgresql.conf.sample still says "seconds", and
guc.c says the default value is "10", and you still do:

+       interval_in_ms = log_startup_progress_interval * 1000;

I checked that this currently does not interpret the value as ms:
|./tmp_install/usr/local/pgsql/bin/postgres -D src/test/regress/tmp_check/data/ -c log_startup_progress_interval=1
|2021-09-07 06:28:58.694 CDT startup[18865] LOG:  redo in progress, elapsed time: 1.00 s, current LSN: 0/E94ED88
|2021-09-07 06:28:59.694 CDT startup[18865] LOG:  redo in progress, elapsed time: 2.00 s, current LSN: 0/10808EE0
|2021-09-07 06:29:00.694 CDT startup[18865] LOG:  redo in progress, elapsed time: 3.00 s, current LSN: 0/126B8C80

(Also, the GUC value is in the range 0..INT_MAX, so multiplying and storing to
another int could overflow.)

I think the convention is to for GUC global vars to be initialized with the
same default as in guc.c, so both should be 10000, like:

+int log_startup_progress_interval = 10 * 1000 /* 10sec */

-- 
Justin