Revert "Temporarily make pg_ctl and server shutdown a whole lot chattier."
authorTom Lane <[email protected]>
Wed, 10 Feb 2016 21:01:04 +0000 (16:01 -0500)
committerTom Lane <[email protected]>
Wed, 10 Feb 2016 21:01:04 +0000 (16:01 -0500)
This reverts commit 3971f64843b02e4a55d854156bd53e46a0588e45 and a
couple of followon debugging commits; I think we've learned what we can
from them.

src/backend/access/transam/xlog.c
src/backend/postmaster/autovacuum.c
src/backend/postmaster/postmaster.c
src/backend/storage/buffer/bufmgr.c
src/backend/storage/ipc/ipc.c
src/backend/storage/smgr/md.c
src/backend/utils/init/miscinit.c
src/bin/pg_ctl/pg_ctl.c
src/include/miscadmin.h

index d173609bc5de529a724cc602380c383074df1ab0..a2846c41b5843e88ad0b4c666519597c871383b6 100644 (file)
@@ -7927,7 +7927,7 @@ ShutdownXLOG(int code, Datum arg)
 {
    /* Don't be chatty in standalone mode */
    ereport(IsPostmasterEnvironment ? LOG : NOTICE,
-           (errmsg("shutting down at %s", current_time_as_str())));
+           (errmsg("shutting down")));
 
    if (RecoveryInProgress())
        CreateRestartPoint(CHECKPOINT_IS_SHUTDOWN | CHECKPOINT_IMMEDIATE);
@@ -7943,28 +7943,15 @@ ShutdownXLOG(int code, Datum arg)
            RequestXLogSwitch();
 
        CreateCheckPoint(CHECKPOINT_IS_SHUTDOWN | CHECKPOINT_IMMEDIATE);
-
-       elog(IsPostmasterEnvironment ? LOG : NOTICE,
-            "shutdown checkpoint complete at %s",
-            current_time_as_str());
    }
    ShutdownCLOG();
-   elog(IsPostmasterEnvironment ? LOG : NOTICE,
-        "ShutdownCLOG() complete at %s",
-        current_time_as_str());
    ShutdownCommitTs();
-   elog(IsPostmasterEnvironment ? LOG : NOTICE,
-        "ShutdownCommitTs() complete at %s",
-        current_time_as_str());
    ShutdownSUBTRANS();
-   elog(IsPostmasterEnvironment ? LOG : NOTICE,
-        "ShutdownSUBTRANS() complete at %s",
-        current_time_as_str());
    ShutdownMultiXact();
 
    /* Don't be chatty in standalone mode */
    ereport(IsPostmasterEnvironment ? LOG : NOTICE,
-           (errmsg("database system is shut down at %s", current_time_as_str())));
+           (errmsg("database system is shut down")));
 }
 
 /*
@@ -8436,9 +8423,6 @@ CreateCheckPoint(int flags)
 
    XLogFlush(recptr);
 
-   elog(IsPostmasterEnvironment ? LOG : NOTICE,
-        "checkpoint WAL record flushed at %s", current_time_as_str());
-
    /*
     * We mustn't write any new WAL after a shutdown checkpoint, or it will be
     * overwritten at next startup.  No-one should even try, this just allows
@@ -8494,9 +8478,6 @@ CreateCheckPoint(int flags)
    UpdateControlFile();
    LWLockRelease(ControlFileLock);
 
-   elog(IsPostmasterEnvironment ? LOG : NOTICE,
-        "pg_control updated at %s", current_time_as_str());
-
    /* Update shared-memory copy of checkpoint XID/epoch */
    SpinLockAcquire(&XLogCtl->info_lck);
    XLogCtl->ckptXidEpoch = checkPoint.nextXidEpoch;
@@ -8514,9 +8495,6 @@ CreateCheckPoint(int flags)
     */
    smgrpostckpt();
 
-   elog(IsPostmasterEnvironment ? LOG : NOTICE,
-        "smgrpostckpt() done at %s", current_time_as_str());
-
    /*
     * Delete old log files (those no longer needed even for previous
     * checkpoint or the standbys in XLOG streaming).
@@ -8532,9 +8510,6 @@ CreateCheckPoint(int flags)
        KeepLogSeg(recptr, &_logSegNo);
        _logSegNo--;
        RemoveOldXlogFiles(_logSegNo, PriorRedoPtr, recptr);
-
-       elog(IsPostmasterEnvironment ? LOG : NOTICE,
-            "RemoveOldXlogFiles() done at %s", current_time_as_str());
    }
 
    /*
@@ -8552,11 +8527,7 @@ CreateCheckPoint(int flags)
     * StartupSUBTRANS hasn't been called yet.
     */
    if (!RecoveryInProgress())
-   {
        TruncateSUBTRANS(GetOldestXmin(NULL, false));
-       elog(IsPostmasterEnvironment ? LOG : NOTICE,
-            "TruncateSUBTRANS() done at %s", current_time_as_str());
-   }
 
    /* Real work is done, but log and update stats before releasing lock. */
    LogCheckpointEnd(false);
@@ -8631,45 +8602,19 @@ CreateEndOfRecoveryRecord(void)
 static void
 CheckPointGuts(XLogRecPtr checkPointRedo, int flags)
 {
-   elog(IsPostmasterEnvironment ? LOG : NOTICE,
-        "CheckPointGuts starting at %s", current_time_as_str());
    CheckPointCLOG();
-   elog(IsPostmasterEnvironment ? LOG : NOTICE,
-        "CheckPointCLOG() done at %s", current_time_as_str());
    CheckPointCommitTs();
-   elog(IsPostmasterEnvironment ? LOG : NOTICE,
-        "CheckPointCommitTs() done at %s", current_time_as_str());
    CheckPointSUBTRANS();
-   elog(IsPostmasterEnvironment ? LOG : NOTICE,
-        "CheckPointSUBTRANS() done at %s", current_time_as_str());
    CheckPointMultiXact();
-   elog(IsPostmasterEnvironment ? LOG : NOTICE,
-        "CheckPointMultiXact() done at %s", current_time_as_str());
    CheckPointPredicate();
-   elog(IsPostmasterEnvironment ? LOG : NOTICE,
-        "CheckPointPredicate() done at %s", current_time_as_str());
    CheckPointRelationMap();
-   elog(IsPostmasterEnvironment ? LOG : NOTICE,
-        "CheckPointRelationMap() done at %s", current_time_as_str());
    CheckPointReplicationSlots();
-   elog(IsPostmasterEnvironment ? LOG : NOTICE,
-        "CheckPointReplicationSlots() done at %s", current_time_as_str());
    CheckPointSnapBuild();
-   elog(IsPostmasterEnvironment ? LOG : NOTICE,
-        "CheckPointSnapBuild() done at %s", current_time_as_str());
    CheckPointLogicalRewriteHeap();
-   elog(IsPostmasterEnvironment ? LOG : NOTICE,
-        "CheckPointLogicalRewriteHeap() done at %s", current_time_as_str());
    CheckPointBuffers(flags);   /* performs all required fsyncs */
-   elog(IsPostmasterEnvironment ? LOG : NOTICE,
-        "CheckPointBuffers() done at %s", current_time_as_str());
    CheckPointReplicationOrigin();
-   elog(IsPostmasterEnvironment ? LOG : NOTICE,
-        "CheckPointReplicationOrigin() done at %s", current_time_as_str());
    /* We deliberately delay 2PC checkpointing as long as possible */
    CheckPointTwoPhase(checkPointRedo);
-   elog(IsPostmasterEnvironment ? LOG : NOTICE,
-        "CheckPointGuts done at %s", current_time_as_str());
 }
 
 /*
index 0914476d33aacee24e21e7fd5ebe1d7128f985b5..e2859df41d6880f89627d807aadbcac52ce2c5df 100644 (file)
@@ -772,8 +772,7 @@ AutoVacLauncherMain(int argc, char *argv[])
    /* Normal exit from the autovac launcher is here */
 shutdown:
    ereport(LOG,
-           (errmsg("autovacuum launcher shutting down at %s",
-                   current_time_as_str())));
+           (errmsg("autovacuum launcher shutting down")));
    AutoVacuumShmem->av_launcherpid = 0;
 
    proc_exit(0);               /* done */
index a5fa1d4720af4d8d0631fd23d11a7618e1208cdc..b16fc28a27dd251f915771df6cb11975b48dd87d 100644 (file)
@@ -2538,8 +2538,7 @@ pmdie(SIGNAL_ARGS)
                break;
            Shutdown = SmartShutdown;
            ereport(LOG,
-                   (errmsg("received smart shutdown request at %s",
-                           current_time_as_str())));
+                   (errmsg("received smart shutdown request")));
 #ifdef USE_SYSTEMD
            sd_notify(0, "STOPPING=1");
 #endif
@@ -2594,8 +2593,7 @@ pmdie(SIGNAL_ARGS)
                break;
            Shutdown = FastShutdown;
            ereport(LOG,
-                   (errmsg("received fast shutdown request at %s",
-                           current_time_as_str())));
+                   (errmsg("received fast shutdown request")));
 #ifdef USE_SYSTEMD
            sd_notify(0, "STOPPING=1");
 #endif
@@ -2658,8 +2656,7 @@ pmdie(SIGNAL_ARGS)
                break;
            Shutdown = ImmediateShutdown;
            ereport(LOG,
-                   (errmsg("received immediate shutdown request at %s",
-                           current_time_as_str())));
+                   (errmsg("received immediate shutdown request")));
 #ifdef USE_SYSTEMD
            sd_notify(0, "STOPPING=1");
 #endif
@@ -2850,9 +2847,6 @@ reaper(SIGNAL_ARGS)
                 */
                Assert(Shutdown > NoShutdown);
 
-               elog(LOG, "checkpointer dead at %s",
-                    current_time_as_str());
-
                /* Waken archiver for the last time */
                if (PgArchPID != 0)
                    signal_child(PgArchPID, SIGUSR2);
@@ -3714,9 +3708,6 @@ PostmasterStateMachine(void)
            if (ReachedNormalRunning)
                CancelBackup();
 
-           elog(LOG, "all children dead at %s",
-                current_time_as_str());
-
            /* Normal exit from the postmaster is here */
            ExitPostmaster(0);
        }
index 3d28946699acd4c71584751db00a510af3bbafc6..7141eb83c68c297de1c67d01e2170828c54c08b8 100644 (file)
@@ -1691,10 +1691,6 @@ BufferSync(int flags)
        UnlockBufHdr(bufHdr);
    }
 
-   elog(IsPostmasterEnvironment ? LOG : NOTICE,
-        "BufferSync(%x) beginning to write %d buffers at %s",
-        flags, num_to_write, current_time_as_str());
-
    if (num_to_write == 0)
        return;                 /* nothing to do */
 
@@ -1749,11 +1745,6 @@ BufferSync(int flags)
                if (num_written >= num_to_write)
                    break;
 
-               if ((num_written % 1024) == 0)
-                   elog(IsPostmasterEnvironment ? LOG : NOTICE,
-                        "BufferSync(%x) wrote %d/%d buffers at %s",
-                        flags, num_written, num_to_write, current_time_as_str());
-
                /*
                 * Sleep to throttle our I/O rate.
                 */
@@ -1765,10 +1756,6 @@ BufferSync(int flags)
            buf_id = 0;
    }
 
-   elog(IsPostmasterEnvironment ? LOG : NOTICE,
-        "BufferSync(%x) done, wrote %d/%d buffers at %s",
-        flags, num_written, num_to_write, current_time_as_str());
-
    /*
     * Update checkpoint statistics. As noted above, this doesn't include
     * buffers written by other backends or bgwriter scan.
index 8db5f9ed326546664e4323e5f2710a4dcc88f6db..cc36b80699b4997cd46baaaef49aa23b5bca3d24 100644 (file)
@@ -98,8 +98,6 @@ static int    on_proc_exit_index,
 void
 proc_exit(int code)
 {
-   bool noisy = AmCheckpointerProcess() || (getpid() == PostmasterPid);
-
    /* Clean up everything that must be cleaned up */
    proc_exit_prepare(code);
 
@@ -142,10 +140,6 @@ proc_exit(int code)
 
    elog(DEBUG3, "exit(%d)", code);
 
-   if (noisy)
-       elog(LOG, "calling exit(%d) at %s",
-            code, current_time_as_str());
-
    exit(code);
 }
 
@@ -157,8 +151,6 @@ proc_exit(int code)
 static void
 proc_exit_prepare(int code)
 {
-   bool noisy = AmCheckpointerProcess() || (getpid() == PostmasterPid);
-
    /*
     * Once we set this flag, we are committed to exit.  Any ereport() will
     * NOT send control back to the main loop, but right back here.
@@ -205,13 +197,8 @@ proc_exit_prepare(int code)
     * possible.
     */
    while (--on_proc_exit_index >= 0)
-   {
-       if (noisy)
-           elog(LOG, "doing on_proc_exit %d at %s",
-                on_proc_exit_index, current_time_as_str());
        (*on_proc_exit_list[on_proc_exit_index].function) (code,
                                  on_proc_exit_list[on_proc_exit_index].arg);
-   }
 
    on_proc_exit_index = 0;
 }
@@ -227,8 +214,6 @@ proc_exit_prepare(int code)
 void
 shmem_exit(int code)
 {
-   bool noisy = AmCheckpointerProcess() || (getpid() == PostmasterPid);
-
    /*
     * Call before_shmem_exit callbacks.
     *
@@ -240,13 +225,8 @@ shmem_exit(int code)
    elog(DEBUG3, "shmem_exit(%d): %d before_shmem_exit callbacks to make",
         code, before_shmem_exit_index);
    while (--before_shmem_exit_index >= 0)
-   {
-       if (noisy)
-           elog(LOG, "doing before_shmem_exit %d at %s",
-                before_shmem_exit_index, current_time_as_str());
        (*before_shmem_exit_list[before_shmem_exit_index].function) (code,
                        before_shmem_exit_list[before_shmem_exit_index].arg);
-   }
    before_shmem_exit_index = 0;
 
    /*
@@ -278,13 +258,8 @@ shmem_exit(int code)
    elog(DEBUG3, "shmem_exit(%d): %d on_shmem_exit callbacks to make",
         code, on_shmem_exit_index);
    while (--on_shmem_exit_index >= 0)
-   {
-       if (noisy)
-           elog(LOG, "doing on_shmem_exit %d at %s",
-                on_shmem_exit_index, current_time_as_str());
        (*on_shmem_exit_list[on_shmem_exit_index].function) (code,
                                on_shmem_exit_list[on_shmem_exit_index].arg);
-   }
    on_shmem_exit_index = 0;
 }
 
index 8552c3d6b84379a1221c81af3299c57d694ccbda..f6b79a9968969dda533777e610e046fd4bab01b8 100644 (file)
@@ -1314,11 +1314,6 @@ mdpostckpt(void)
        if (entry->cycle_ctr == mdckpt_cycle_ctr)
            break;
 
-       if ((list_length(pendingUnlinks) % 1024) == 0)
-           elog(IsPostmasterEnvironment ? LOG : NOTICE,
-                "in mdpostckpt, %d unlinks remain to do at %s",
-                list_length(pendingUnlinks), current_time_as_str());
-
        /* Unlink the file */
        path = relpathperm(entry->rnode, MAIN_FORKNUM);
        if (unlink(path) < 0)
index 03cbb6e3499740925be195745df74db2864fb55e..b7bab56099fab43d00d25b04f9e4f39ee163aed4 100644 (file)
@@ -691,31 +691,6 @@ GetUserNameFromId(Oid roleid, bool noerr)
    return result;
 }
 
-/*
- * Quick hack.
- */
-const char *
-current_time_as_str(void)
-{
-   static char buf[128];
-   struct timeval now_timeval;
-   pg_time_t   now;
-   char        msbuf[8];
-
-   gettimeofday(&now_timeval, NULL);
-   now = (pg_time_t) now_timeval.tv_sec;
-
-   pg_strftime(buf, sizeof(buf),
-   /* leave room for milliseconds... */
-               "%Y-%m-%d %H:%M:%S     %Z",
-               pg_localtime(&now, log_timezone));
-
-   /* 'paste' milliseconds into place... */
-   sprintf(msbuf, ".%03d", (int) (now_timeval.tv_usec / 1000));
-   memcpy(buf + 19, msbuf, 4);
-
-   return buf;
-}
 
 /*-------------------------------------------------------------------------
  *             Interlock-file support
@@ -749,9 +724,6 @@ UnlinkLockFiles(int status, Datum arg)
    }
    /* Since we're about to exit, no need to reclaim storage */
    lock_files = NIL;
-
-   if (IsPostmasterEnvironment)
-       elog(LOG, "lock files all released at %s", current_time_as_str());
 }
 
 /*
index c970a733801132d72fe8d8a783866429c70bba77..9da38c4e6f06502fcbd2914e61df6d2abda5c208 100644 (file)
@@ -946,32 +946,6 @@ do_start(void)
 }
 
 
-/*
- * Quick hack.
- */
-const char *
-current_time_as_str(void)
-{
-   static char buf[128];
-   struct timeval now_timeval;
-   time_t  now;
-   char        msbuf[8];
-
-   gettimeofday(&now_timeval, NULL);
-   now = (time_t) now_timeval.tv_sec;
-
-   strftime(buf, sizeof(buf),
-            /* leave room for milliseconds... */
-            "%Y-%m-%d %H:%M:%S     %Z",
-            localtime(&now));
-
-   /* 'paste' milliseconds into place... */
-   sprintf(msbuf, ".%03d", (int) (now_timeval.tv_usec / 1000));
-   memcpy(buf + 19, msbuf, 4);
-
-   return buf;
-}
-
 static void
 do_stop(void)
 {
@@ -1024,12 +998,7 @@ do_stop(void)
                        "Shutdown will not complete until pg_stop_backup() is called.\n\n"));
        }
 
-       if (!silent_mode)
-       {
-           fprintf(stdout, _("waiting for server to shut down at %s..."),
-                   current_time_as_str());
-           fflush(stdout);
-       }
+       print_msg(_("waiting for server to shut down..."));
 
        for (cnt = 0; cnt < wait_seconds; cnt++)
        {
@@ -1046,8 +1015,7 @@ do_stop(void)
        {
            print_msg(_(" failed\n"));
 
-           write_stderr(_("%s: server does not shut down at %s\n"),
-                        progname, current_time_as_str());
+           write_stderr(_("%s: server does not shut down\n"), progname);
            if (shutdown_mode == SMART_MODE)
                write_stderr(_("HINT: The \"-m fast\" option immediately disconnects sessions rather than\n"
                          "waiting for session-initiated disconnection.\n"));
index ec535a3bc4346a82b36ea2fc4c689cd34cb1047b..cc7833e6cda9eb72e70c66f0786b74923911b22c 100644 (file)
@@ -448,7 +448,6 @@ extern char *local_preload_libraries_string;
 #define LOCK_FILE_LINE_LISTEN_ADDR 6
 #define LOCK_FILE_LINE_SHMEM_KEY   7
 
-extern const char *current_time_as_str(void);
 extern void CreateDataDirLockFile(bool amPostmaster);
 extern void CreateSocketLockFile(const char *socketfile, bool amPostmaster,
                     const char *socketDir);