Date: Wed, 29 Sep 2021 14:36:14 -0300
From: Alvaro Herrera <alvherre@alvh.no-ip.org>
To: Nitin Jadhav <nitinjadhavpostgres@gmail.com>
Cc: Robert Haas <robertmhaas@gmail.com>,
	Justin Pryzby <pryzby@telsasoft.com>,
	Michael Paquier <michael@paquier.xyz>,
	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>,
	"pgsql-hackers@postgresql.org" <pgsql-hackers@postgresql.org>
Subject: Re: when the startup process doesn't (logging startup delays)
Message-ID: <202109291736.w3lzq4prep3p@alvherre.pgsql>
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Disposition: inline
Content-Transfer-Encoding: 8bit
In-Reply-To: 
 <CAMm1aWae1qaxQC+83VZd0NVpzO==n3cxMoqedZvU=TWpmo-uSg@mail.gmail.com>
Archived-At: 
 <https://www.postgresql.org/message-id/202109291736.w3lzq4prep3p%40alvherre.pgsql>
Precedence: bulk

So, I've wondered about this part all along:

> +/*
> + * Calculates the timestamp at which the next timer should expire and enables
> + * the timer accordingly.
> + */
> +static void
> +reset_startup_progress_timeout(TimestampTz now)
> +{
> +	TimestampTz next_timeout;
> +
> +	next_timeout = TimestampTzPlusMilliseconds(scheduled_startup_progress_timeout,
> +											   log_startup_progress_interval);
> +	if (next_timeout < now)
> +	{
> +		/*
> +		 * Either the timeout was processed so late that we missed an
> +		 * entire cycle or system clock was set backwards.
> +		 */
> +		next_timeout = TimestampTzPlusMilliseconds(now, log_startup_progress_interval);
> +	}
> +
> +	enable_timeout_at(STARTUP_PROGRESS_TIMEOUT, next_timeout);

Why is it that we set the next timeout to fire not at "now + interval"
but at "when-it-should-have-fired-but-didn't + interval"?  As a user, if
I request a message to be logged every N milliseconds, and one
of them is a little bit delayed, then (assuming I set it to 10s) I still
expect the next one to occur at now+10s.  I don't expect the next at
"now+5s" if one is delayed 5s.

In other words, I think this function should just be
  enable_timeout_after(STARTUP_PROGRESS_TIMEOUT, log_startup_progress_interval);

This means you can remove the scheduled_startup_progress_timeout
variable.

-- 
Álvaro Herrera           39°49'30"S 73°17'W  —  https://www.EnterpriseDB.com/
"No hay ausente sin culpa ni presente sin disculpa" (Prov. francés)