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

On Wed, Jul 21, 2021 at 12:52 PM Nitin Jadhav
<nitinjadhavpostgres@gmail.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.