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

Modified the reset_startup_progress_timeout() to take the second
parameter which indicates whether it is called for initialization or
for resetting. Without this parameter there is a problem if we call
init_startup_progress() more than one time if there is no call to
ereport_startup_progress() in between as the code related to disabling
the timer has been removed.

reset_startup_progress_timeout(TimeStampTz now, bool is_init)
{
if (is_init)
next_timeout = now + interval;
else
{
next_timeout = scheduled_startup_progress_timeout + interval;
if (next_timeout < now)
{
// Either the timeout was processed so late that we missed an
entire cycle,
// or the system clock was set backwards.
next_timeout = now + interval;
}
enable_timeout_at(next_timeout);
scheduled_startup_progress_timeout = next_timeout;
}
}

I have incorporated this in the attached patch. Please correct me if I am wrong.

> This makes sense, but I think I'd like to have all the functions in
> this patch use names_like_this() rather than NamesLikeThis().

I have changed all the function names accordingly. But I would like to
know why it should be names_like_this() as there are many functions
with the format NamesLikeThis(). I would like to understand when to
use what, just to incorporate in the future patches.

> Hmm, yeah, that seems good, but given this change, maybe the variables
> need a little renaming. Like change last_startup_progress_timeout to
> scheduled_startup_progress_timeout, perhaps.

Right. Changed the variable name.

> I guess this one needs to return a Boolean, actually.

Yes.

> reset_startup_progress_timeout(TimeStampTz now)
> {
> next_timeout = last_startup_progress_timeout + interval;
> if (next_timeout < now)
> {
> // Either the timeout was processed so late that we missed an entire cycle,
> // or the system clock was set backwards.
> next_timeout = now + interval;
> }
> enable_timeout_at(next_timeout);
> last_startup_progress_timeout = next_timeout;
> }

As per the above logic, I would like to discuss 2 cases.

Case-1:
First scheduled timeout is after 1 sec. But the time out occurred
after 1.5 sec. So the log msg prints after 1.5 sec. Next timer is
scheduled after 2 sec (scheduled_startup_progress_timeout + interval).
The condition (next_timeout < now) gets evaluated to false and
everything goes smooth.

Case-2:
First scheduled timeout is after 1 sec. But the timeout occurred after
2.5 sec. So the log msg prints after 2.5 sec. Now next time is
scheduled after 2 sec (scheduled_startup_progress_timeout + interval).
So the condition (next_timeout < now) will fail and the next_timeout
will get reset to 3.5 sec (2.5 + 1) and it continues. Is this
behaviour ok or should we set the next_timeout to 3 sec. Please share
your thoughts on this.

Thanks & Regards,
Nitin Jadhav

On Thu, Aug 5, 2021 at 7:49 PM Robert Haas <robertmhaas(at)gmail(dot)com> wrote:
>
> On Thu, Aug 5, 2021 at 7:41 AM Nitin Jadhav
> <nitinjadhavpostgres(at)gmail(dot)com> wrote:
> > This seems a little confusing. As we are setting
> > last_startup_progress_timeout = now and then calling
> > reset_startup_progress_timeout() which will calculate the next_time
> > based on the value of last_startup_progress_timeout initially and
> > checks whether next_timeout is less than now. It doesn't make sense to
> > me. I feel we should calculate the next_timeout based on the time that
> > it is supposed to fire next time. So we should set
> > last_startup_progress_timeout = next_timeout after enabling the timer.
> > Also I feel with the 2 functions mentioned above, we also need
> > InitStartupProgress() which sets the initial value to
> > startupProcessOpStartTime which is used to calculate the time
> > difference and display in the logs. I could see those functions like
> > below.
> >
> > InitStartupProgress(void)
> > {
> > startupProcessOpStartTime = GetCurrentTimestamp();
> > ResetStartupProgressTimeout(startupProcessOpStartTime);
> > }
>
> This makes sense, but I think I'd like to have all the functions in
> this patch use names_like_this() rather than NamesLikeThis().
>
> > reset_startup_progress_timeout(TimeStampTz now)
> > {
> > next_timeout = last_startup_progress_timeout + interval;
> > if (next_timeout < now)
> > {
> > // Either the timeout was processed so late that we missed an entire cycle,
> > // or the system clock was set backwards.
> > next_timeout = now + interval;
> > }
> > enable_timeout_at(next_timeout);
> > last_startup_progress_timeout = next_timeout;
> > }
>
> Hmm, yeah, that seems good, but given this change, maybe the variables
> need a little renaming. Like change last_startup_progress_timeout to
> scheduled_startup_progress_timeout, perhaps.
>
> > startup_progress_timeout_has_expired()
> > {
> > if (!startup_progress_timer_expired)
> > return;
> > now = GetCurrentTimestamp();
> > // compute timestamp difference based on startupProcessOpStartTime
> > reset_startup_progress_timeout(now);
> > }
>
> I guess this one needs to return a Boolean, actually.
>
> --
> Robert Haas
> EDB: http://www.enterprisedb.com