Re: when the startup process doesn't (logging startup delays) - Mailing list pgsql-hackers

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@gmail.com> wrote:
>
> On Thu, Aug 5, 2021 at 7:41 AM Nitin Jadhav
> <nitinjadhavpostgres@gmail.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