From c5e9b771275b93b09eec6b760677fe6c5e726ab2 Mon Sep 17 00:00:00 2001 From: Tom Lane Date: Wed, 10 Feb 2016 16:01:04 -0500 Subject: [PATCH] Revert "Temporarily make pg_ctl and server shutdown a whole lot chattier." 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 | 59 +---------------------------- src/backend/postmaster/autovacuum.c | 3 +- src/backend/postmaster/postmaster.c | 15 ++------ src/backend/storage/buffer/bufmgr.c | 13 ------- src/backend/storage/ipc/ipc.c | 25 ------------ src/backend/storage/smgr/md.c | 5 --- src/backend/utils/init/miscinit.c | 28 -------------- src/bin/pg_ctl/pg_ctl.c | 36 +----------------- src/include/miscadmin.h | 1 - 9 files changed, 8 insertions(+), 177 deletions(-) diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c index d173609bc5..a2846c41b5 100644 --- a/src/backend/access/transam/xlog.c +++ b/src/backend/access/transam/xlog.c @@ -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()); } /* diff --git a/src/backend/postmaster/autovacuum.c b/src/backend/postmaster/autovacuum.c index 0914476d33..e2859df41d 100644 --- a/src/backend/postmaster/autovacuum.c +++ b/src/backend/postmaster/autovacuum.c @@ -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 */ diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c index a5fa1d4720..b16fc28a27 100644 --- a/src/backend/postmaster/postmaster.c +++ b/src/backend/postmaster/postmaster.c @@ -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); } diff --git a/src/backend/storage/buffer/bufmgr.c b/src/backend/storage/buffer/bufmgr.c index 3d28946699..7141eb83c6 100644 --- a/src/backend/storage/buffer/bufmgr.c +++ b/src/backend/storage/buffer/bufmgr.c @@ -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. diff --git a/src/backend/storage/ipc/ipc.c b/src/backend/storage/ipc/ipc.c index 8db5f9ed32..cc36b80699 100644 --- a/src/backend/storage/ipc/ipc.c +++ b/src/backend/storage/ipc/ipc.c @@ -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; } diff --git a/src/backend/storage/smgr/md.c b/src/backend/storage/smgr/md.c index 8552c3d6b8..f6b79a9968 100644 --- a/src/backend/storage/smgr/md.c +++ b/src/backend/storage/smgr/md.c @@ -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) diff --git a/src/backend/utils/init/miscinit.c b/src/backend/utils/init/miscinit.c index 03cbb6e349..b7bab56099 100644 --- a/src/backend/utils/init/miscinit.c +++ b/src/backend/utils/init/miscinit.c @@ -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()); } /* diff --git a/src/bin/pg_ctl/pg_ctl.c b/src/bin/pg_ctl/pg_ctl.c index c970a73380..9da38c4e6f 100644 --- a/src/bin/pg_ctl/pg_ctl.c +++ b/src/bin/pg_ctl/pg_ctl.c @@ -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")); diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h index ec535a3bc4..cc7833e6cd 100644 --- a/src/include/miscadmin.h +++ b/src/include/miscadmin.h @@ -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);