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

> I am not sure I am getting the code flow correctly. From CloseStartupProgress()
> naming it seems, it corresponds to InitStartupProgress() but what it is doing
> is similar to LogStartupProgress(). I think it should be renamed to be inlined
> with LogStartupProgress(), IMO.

Renamed CloseStartupProgress() to LogStartupProgressComplete().

> This part should be an assertion, it's the developer's responsibility to call
> correctly.

This code is not required at all due to the fix of the next comment.

> Since we do have a separate call for the in-progress operation and the
> end-operation, only a single enum would have been enough. If we do this, then I
> think we should remove get_startup_process_operation_string() move messages to
> the respective function.

Fixed.

> I'd really like to see this enabled by default, say with a default
> interval of 10 seconds. If it has to be enabled explicitly, most
> people won't, but I think a lot of people would benefit from knowing
> why their system is slow to start up when that sort of thing happens.
> I don't see much downside to having it on by default either, since it
> shouldn't be expensive. I think the GUC's units should be seconds, not
> milliseconds, though.

I agree that it is better to enable it by default. Changed the code
accordingly and changed the GUC's units to seconds.

> The messages you've added are capitalized, but the ones PostgreSQL
> has currently are not. You should conform to the existing style.

Fixed.

> The "crash recovery complete" message looks redundant with the "redo
> done" message. Also, in my mind, "redo" is one particular phase of
> crash recovery, so it looks really odd that "crash recovery" finishes
> first and then "redo" finishes. I think some thought is needed about
> the terminology here.

Yes. "redo" is one phase of the crash recovery. Even "resetting
unlogged relations" is also a part of the crash recovery. These 2 are
the major time consuming operations of the crash recovery task. There
is a separate log message to indicate the progress of "resetting the
unlogged relations". So instead of saying 'performing crash recovery",
it is better to say "redo in progress" and not add any additional
message at the end of redo, instead retain the existing message to
avoid redundancy.

> I'm not clear why I get a message about the data directory fsync but
> not about resetting unlogged relations. I wasn't really expecting to
> get a message about things that completed in less than the configured
> interval, although I find that I don't mind having it there either.
> But then it seems like it should be consistent across the various
> things we're timing, and resetting unlogged relations should certainly
> be one of those.

It is the same across all the things we'are timing. I was able to see
those messages on my machine. I feel there is not much overhead of
logging one message at the end of the operation even though it
completes within the configured interval. Following are the log
messages shown on my machine.

2021-07-20 18:47:32.046 IST [102230] LOG: listening on IPv4 address
"127.0.0.1", port 5445
2021-07-20 18:47:32.048 IST [102230] LOG: listening on Unix socket
"/tmp/.s.PGSQL.5445"
2021-07-20 18:47:32.051 IST [102234] LOG: database system was
interrupted; last known up at 2021-07-20 18:46:27 IST
2021-07-20 18:47:32.060 IST [102234] LOG: data directory sync (fsync)
complete after 0.00 s
2021-07-20 18:47:32.060 IST [102234] LOG: database system was not
properly shut down; automatic recovery in progress
2021-07-20 18:47:32.063 IST [102234] LOG: unlogged relations reset after 0.00 s
2021-07-20 18:47:32.063 IST [102234] LOG: redo starts at 0/14EF418
.2021-07-20 18:47:33.063 IST [102234] LOG: redo in progress, elapsed
time: 1.00 s, current LSN: 0/5C13D28
.2021-07-20 18:47:34.063 IST [102234] LOG: redo in progress, elapsed
time: 2.00 s, current LSN: 0/A289160
.2021-07-20 18:47:35.063 IST [102234] LOG: redo in progress, elapsed
time: 3.00 s, current LSN: 0/EE2DE10
2021-07-20 18:47:35.563 IST [102234] LOG: invalid record length at
0/115C63E0: wanted 24, got 0
2021-07-20 18:47:35.563 IST [102234] LOG: redo done at 0/115C63B8
system usage: CPU: user: 3.58 s, system: 0.14 s, elapsed: 3.50 s
2021-07-20 18:47:35.564 IST [102234] LOG: unlogged relations reset after 0.00 s
2021-07-20 18:47:35.706 IST [102230] LOG: database system is ready to
accept connections

> The way you've coded this has some drift. In a perfect world, I'd
> get a progress report at 1000.00 ms, 2000.00 ms, 3000.00 ms, etc.
> That's never going to be the case, because there's always going to be
> a slightly delay in responding to the timer interrupt. However, as
> you've coded it, the delay increases over time. The first "Performing
> crash recovery" message is only 373 ms late, but the last one is 4916
> ms late. To avoid this, you want to reschedule the timer interrupt
> based on the time the last one was supposed to fire, not the time it
> actually did fire. (Exception: If the time it actually did fire is
> before the time it was supposed to fire, then use the time it actually
> did fire instead. This protects against the system clock being set
> backwards.)

I have rescheduled the timer interrupt based on the time the last one
was supposed to fire, not the time it actually did fire. Now I am able
to see the messages when the timer is timed out and it is very close
to the configured interval. But I did not find a scenario when the
above mentioned exception can occur. Kindly let me know if I am wrong
in the approach.

> 1) A new line between function return value and the function name:
> +void CloseStartupProgress(StartupProcessOp operation)
> +{
> Like below:
> +void
> +CloseStartupProgress(StartupProcessOp operation)
> +{

Fixed.

> 2) Add an entry in the commit fest, if it's not done yet. That way,
> the patch gets tested on many platforms.

I have an entry in the sept commitfest
https://commitfest.postgresql.org/34/3261/

> 3) Replace "zero" with the number "0".
> + # -1 disables the feature, zero logs all

Fixed.

> 4) I think we can just rename InitStartupProgress to
> EnableStartupProgress or EnableStartupOpProgress to be more in sync
> with what it does.

I feel 'Init' is more appropriate than 'enable' here. As it not only
enables the timer but also initializes some variables. Timer enabling
can also be interpreted as initialization. So in common 'init' is
better than 'enable'.

> 5) Do we need the GetCurrentOperationStartTimestamp function at all?
> It does nothing great actually, you might have referred to
> GetCurrentTimestamp which does a good amount of work that qualifies to
> be inside a function. Can't we just use the operationStartTimestamp
> variable? Can we rename operationStartTimestamp (I don't think we need
> to specify Timestamp in a variable name) to startup_op_start_time or
> some other better name?

Changed it to 'startupProcessOpStartTime'.

> 6) I think you can transform below
> + /* If the feature is disabled, then no need to proceed further. */
> + if (log_startup_progress_interval < 0)
> + return;
> to
> + /* If the feature is disabled, then no need to proceed further. */
> + if (log_startup_progress_interval == -1)
> + return;
> as -1 means feature disabled and values < -1 are not allowed to be set at all.

I feel that should be ok. As '<0' includes '-1'. So it does our job. I
can change it if it is really required to do so.

> 7) Isn't RECOVERY_IN_PROGRESS supposed to be REDO_IN_PRGRESS? Because,
> "recovery in progress" generally applies to the entire startup process
> right? Put it another way, the startup process as a whole does the
> entire recovery, and you have the RECOVERY_IN_PROGRESS in the redo
> phase of the entire startup process.

Changed it as part of the earlier comment's fix. Modified the message
also to 'redo in progress' rather than 'recovery in progress'.

> 8) Why do we need to call get_startup_process_operation_string here?
> Can't you directly use the error message text?
> if (operation == RECOVERY_IN_PROGRESS)
> ereport(LOG,
> (errmsg("%s, elapsed time: %ld.%03d ms, current LSN: %X/%X",
> get_startup_process_operation_string(operation),

Fixed it as part of an earlier comment.

> 9) Do you need error handling in the default case of
> get_startup_process_operation_string? Instead, how about an assertion,
> Assert(operation >= SYNCFS_IN_PROGRESS && operation <=
> RESET_UNLOGGED_REL_END);?
> default:
> ereport(ERROR,
> (errmsg("unrecognized operation (%d) in startup
>progress update",
> operation)));

It is better to have a default case. Assert is difficult to maintain
if there are any modifications to the operations.

> 10) I personally didn't like the name
> get_startup_process_operation_string. How about get_startup_op_string?

I have removed it as part of fixing the earlier comment.

> 11) As pointed out by Robert, the error log message should start with
> small letters.
> "syncing data directory (syncfs)");
> "syncing data directory (fsync)");
> "performing crash recovery");
> "resetting unlogged relations");
> In general, the error log message should start with small letters and
> not end with ".". The detail/hit messages should start with capital
> letters and end with "."

Thanks for the information.

> 12) How about starting SYNCFS_IN_PROGRESS = 1, and leaving 0 for some
> unknown value?
> typedef enum StartupProcessOp
> {
> /* Codes for in-progress operations */
> SYNCFS_IN_PROGRESS = 1,

I don't find any reason to do so. So not changed. Kindly let me know
if there is any specific reason which would help changing it.

> 13) Can we combine LogStartupProgress and CloseStartupProgress? Let's
> have a single function LogStartupProgress(StartupProcessOp operation,
> const char *path, bool start);, and differentiate the functionality
> with the start flag.

The function becomes complex and it will affect the readability.

> 14) Can we move log_startup_progress_interval declaration from guc.h
> and guc.c to xlog.h and xlog.c? Because it makes more sense to be
> there, similar to the other GUCs under /* these variables are GUC
> parameters related to XLOG */ in xlog.h.

Fixed.

Please find the v5 patch attached. Kindly let me know your comments.

On Sat, Jul 10, 2021 at 1:51 PM Bharath Rupireddy
<bharath(dot)rupireddyforpostgres(at)gmail(dot)com> wrote:
>
> On Mon, Jun 21, 2021 at 12:06 PM Nitin Jadhav
> <nitinjadhavpostgres(at)gmail(dot)com> wrote:
> > That was by mistake and I have corrected it in the attached patch.
>
> Thanks for the patch. Here are some comments. Please ignore if I
> repeat any of the comments given previously, as I didn't look at the
> entire thread.
>
> 1) A new line between function return value and the function name:
> +void CloseStartupProgress(StartupProcessOp operation)
> +{
> Like below:
> +void
> +CloseStartupProgress(StartupProcessOp operation)
> +{
>
> 2) Add an entry in the commit fest, if it's not done yet. That way,
> the patch gets tested on many platforms.
>
> 3) Replace "zero" with the number "0".
> + # -1 disables the feature, zero logs all
>
> 4) I think we can just rename InitStartupProgress to
> EnableStartupProgress or EnableStartupOpProgress to be more in sync
> with what it does.
> +/*
> + * Sets the start timestamp of the current operation and also enables the
> + * timeout for logging the progress of startup process.
> + */
> +void
> +InitStartupProgress(void)
> +{
>
> 5) Do we need the GetCurrentOperationStartTimestamp function at all?
> It does nothing great actually, you might have referred to
> GetCurrentTimestamp which does a good amount of work that qualifies to
> be inside a function. Can't we just use the operationStartTimestamp
> variable? Can we rename operationStartTimestamp (I don't think we need
> to specify Timestamp in a variable name) to startup_op_start_time or
> some other better name?
> +/*
> + * Fetches the start timestamp of the current operation.
> + */
> +TimestampTz
> +GetCurrentOperationStartTimestamp(void)
> +{
>
> 6) I think you can transform below
> + /* If the feature is disabled, then no need to proceed further. */
> + if (log_startup_progress_interval < 0)
> + return;
> to
> + /* If the feature is disabled, then no need to proceed further. */
> + if (log_startup_progress_interval == -1)
> + return;
> as -1 means feature disabled and values < -1 are not allowed to be set at all.
>
> 7) Isn't RECOVERY_IN_PROGRESS supposed to be REDO_IN_PRGRESS? Because,
> "recovery in progress" generally applies to the entire startup process
> right? Put it another way, the startup process as a whole does the
> entire recovery, and you have the RECOVERY_IN_PROGRESS in the redo
> phase of the entire startup process.
>
> 8) Why do we need to call get_startup_process_operation_string here?
> Can't you directly use the error message text?
> if (operation == RECOVERY_IN_PROGRESS)
> ereport(LOG,
> (errmsg("%s, elapsed time: %ld.%03d ms, current LSN: %X/%X",
> get_startup_process_operation_string(operation),
>
> 9) Do you need error handling in the default case of
> get_startup_process_operation_string? Instead, how about an assertion,
> Assert(operation >= SYNCFS_IN_PROGRESS && operation <=
> RESET_UNLOGGED_REL_END);?
> default:
> ereport(ERROR,
> (errmsg("unrecognized operation (%d) in startup
> progress update",
> operation)));
> 10) I personally didn't like the name
> get_startup_process_operation_string. How about get_startup_op_string?
>
> 11) As pointed out by Robert, the error log message should start with
> small letters.
> "syncing data directory (syncfs)");
> "syncing data directory (fsync)");
> "performing crash recovery");
> "resetting unlogged relations");
> In general, the error log message should start with small letters and
> not end with ".". The detail/hit messages should start with capital
> letters and end with "."
> ereport(ERROR,
> (errcode(ERRCODE_FEATURE_NOT_SUPPORTED),
> errmsg("only B-Tree indexes are supported as targets
> for verification"),
> errdetail("Relation \"%s\" is not a B-Tree index.",
> RelationGetRelationName(rel))));
> ereport(ERROR,
> (errcode(ERRCODE_INSUFFICIENT_PRIVILEGE),
> errmsg("sslcert and sslkey are superuser-only"),
> errhint("User mappings with the sslcert or
> sslkey options set may only be created or modified by the
> superuser")));
>
> 12) How about starting SYNCFS_IN_PROGRESS = 1, and leaving 0 for some
> unknown value?
> typedef enum StartupProcessOp
> {
> /* Codes for in-progress operations */
> SYNCFS_IN_PROGRESS = 1,
>
> 13) Can we combine LogStartupProgress and CloseStartupProgress? Let's
> have a single function LogStartupProgress(StartupProcessOp operation,
> const char *path, bool start);, and differentiate the functionality
> with the start flag.
>
> 14) Can we move log_startup_progress_interval declaration from guc.h
> and guc.c to xlog.h and xlog.c? Because it makes more sense to be
> there, similar to the other GUCs under /* these variables are GUC
> parameters related to XLOG */ in xlog.h.
>
> Regards,
> Bharath Rupireddy.