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

On Wed, Jul 21, 2021 at 12:52 PM Nitin Jadhav
<nitinjadhavpostgres(at)gmail(dot)com> wrote:
> Please find the v5 patch attached. Kindly let me know your comments.

Thanks for the patch. Here are some comments on v5:
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]:

2) Why isn't there a
LogStartupProgressComplete(STARTUP_PROCESS_OP_REDO)? Is it because of
the below existing log message?
ereport(LOG,
(errmsg("redo done at %X/%X system usage: %s",
LSN_FORMAT_ARGS(ReadRecPtr),
pg_rusage_show(&ru0))));

3) I think it should be, "," after occurred instead of "."
+ * elapsed or not. TRUE if timeout occurred, FALSE otherwise.
instead of
+ * elapsed or not. TRUE if timeout occurred. FALSE otherwise.

[1]
+/*
+ * Logs the progress of the operations performed during the startup process.
+ * is_complete true/false indicates that the operation is finished/
+ * in-progress respectively.
+ */
+void
+LogStartupProgress(StartupProcessOp op, const char *path,
+ bool is_complete)
+{
+ long secs;
+ int usecs;
+ int elapsed_ms;
+ int interval_in_ms;
+
+ /* If not called from the startup process then this feature is
of no use. */
+ if (!AmStartupProcess())
+ return;
+
+ /* If the feature is disabled, then no need to proceed further. */
+ if (log_startup_progress_interval < 0)
+ return;
+
+ /*
+ * If the operation is in-progress and the timeout hasn't occurred, then
+ * no need to log the details.
+ */
+ if (!is_complete && !logStartupProgressTimeout)
+ return;
+
+ /* Timeout has occurred. */
+ TimestampDifference(startupProcessOpStartTime,
+ GetCurrentTimestamp(),
+ &secs, &usecs);
+
+ /*
+ * If the operation is in-progress, enable the timer for the next log
+ * message based on the time that current log message timer
was supposed to
+ * fire.
+ */
+ if (!is_complete)
+ {
+ elapsed_ms = (secs * 1000) + (usecs / 1000);
+ interval_in_ms = log_startup_progress_interval * 1000;
+ enable_timeout_after(LOG_STARTUP_PROGRESS_TIMEOUT,
+
(interval_in_ms - (elapsed_ms % interval_in_ms)));
+ }
+
+ switch(op)
+ {
+ case STARTUP_PROCESS_OP_SYNCFS:
+ {
+ if (is_complete)
+ ereport(LOG,
+ (errmsg("data
directory sync (syncfs) complete after %ld.%02d s",
+
secs, (usecs / 10000))));
+ else
+ ereport(LOG,
+
(errmsg("syncing data directory (syncfs), elapsed time: %ld.%02d s,
current path: %s",
+
secs, (usecs / 10000), path)));
+ }
+ break;
+ case STARTUP_PROCESS_OP_FSYNC:
+ {
+ if (is_complete)
+ ereport(LOG,
+ (errmsg("data
directory sync (fsync) complete after %ld.%02d s",
+
secs, (usecs / 10000))));
+ else
+ ereport(LOG,
+
(errmsg("syncing data directory (fsync), elapsed time: %ld.%02d s,
current path: %s",
+
secs, (usecs / 10000), path)));
+ }
+ break;
+ case STARTUP_PROCESS_OP_REDO:
+ {
+ /*
+ * No need to log redo completion
status here, as it will be
+ * done in the caller.
+ */
+ if (!is_complete)
+ ereport(LOG,
+ (errmsg("redo
in progress, elapsed time: %ld.%02d s, current LSN: %X/%X",
+
secs, (usecs / 10000), LSN_FORMAT_ARGS(ReadRecPtr))));
+ }
+ break;
+ case STARTUP_PROCESS_OP_RESET_UNLOGGED_REL:
+ {
+ if (is_complete)
+ ereport(LOG,
+
(errmsg("unlogged relations reset after %ld.%02d s",
+
secs, (usecs / 10000))));
+ else
+ ereport(LOG,
+
(errmsg("resetting unlogged relations, elapsed time: %ld.%02d s,
current path: %s",
+
secs, (usecs / 10000), path)));
+ }
+ break;
+ default:
+ ereport(ERROR,
+ (errmsg("unrecognized
operation (%d) in startup progress update",
+ op)));
+ break;
+ }
+
+ if (is_complete)
+ disable_timeout(LOG_STARTUP_PROGRESS_TIMEOUT, false);
+ else
+ logStartupProgressTimeout = false;
+}

Regards,
Bharath Rupireddy.