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

On Mon, Jul 26, 2021 at 10:13:09AM -0400, Robert Haas wrote:
> I don't think walkdir() has any business calling LogStartupProgress()
> at all. It's supposed to be a generic function, not one that is only
> available to be called from the startup process, or has different
> behavior there. From my point of view, the right thing is to put the
> logging calls into the particular callbacks that SyncDataDirectory()
> uses.

You're right - this is better.

On Wed, Jul 21, 2021 at 04:47:32PM +0530, Bharath Rupireddy wrote:
> > > 1) I still don't see the need for two functions LogStartupProgress and
> > > LogStartupProgressComplete. Most of the code is duplicate. I think we
> > > can just do it with a single function something like [1]:
> >
> > I agree that one function can do this more succinctly.  I think it's best to
> > use a separate enum value for START operations and END operations.
> 
> Maybe I'm missing something here, but I don't understand the purpose
> of this. You can always combine two functions into one, but it's only
> worth doing if you end up with less code, which doesn't seem to be the
> case here.

 4 files changed, 39 insertions(+), 71 deletions(-)

> ... but I'm not exactly sure how to get there from here. Having only
> LogStartupProgress() but having it do a giant if-statement to figure
> out whether we're mid-phase or end-of-phase does not seem like the
> right approach.

I used a bool arg and negation to handle within a single switch.  Maybe it's
cleaner to use a separate enum value for each DONE, and set a local done flag.

 startup[29675] LOG:  database system was interrupted; last known up at 2021-07-26 10:23:04 CDT
 startup[29675] LOG:  syncing data directory (fsync), elapsed time: 1.38 s, current path: ./pg_ident.conf
 startup[29675] LOG:  data directory sync (fsync) complete after 1.72 s
 startup[29675] LOG:  database system was not properly shut down; automatic recovery in progress
 startup[29675] LOG:  resetting unlogged relations (cleanup) complete after 0.00 s
 startup[29675] LOG:  redo starts at 0/17BE500
 startup[29675] LOG:  redo in progress, elapsed time: 1.00 s, current LSN: 0/35D7CB8
 startup[29675] LOG:  redo in progress, elapsed time: 2.00 s, current LSN: 0/54A6918
 startup[29675] LOG:  redo in progress, elapsed time: 3.00 s, current LSN: 0/7370570
 startup[29675] LOG:  redo in progress, elapsed time: 4.00 s, current LSN: 0/924D8A0
 startup[29675] LOG:  redo done at 0/9FFFFB8 system usage: CPU: user: 4.28 s, system: 0.15 s, elapsed: 4.44 s
 startup[29675] LOG:  resetting unlogged relations (init) complete after 0.03 s
 startup[29675] LOG:  checkpoint starting: end-of-recovery immediate
 startup[29675] LOG:  checkpoint complete: wrote 9872 buffers (60.3%); 0 WAL file(s) added, 0 removed, 8 recycled;
write=0.136s, sync=0.801 s, total=1.260 s; sync files=21, longest=0.774 s, average=B