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

@@ -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());
 }
 
 /*

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",
+			(errmsg("autovacuum launcher shutting down")));
-					current_time_as_str())));
 	AutoVacuumShmem->av_launcherpid = 0;
 
 	proc_exit(0);				/* done */

src/backend/postmaster/postmaster.c

@@ -2538,8 +2538,7 @@ pmdie(SIGNAL_ARGS)
 				break;
 			Shutdown = SmartShutdown;
 			ereport(LOG,
-					(errmsg("received smart shutdown request at %s",
+					(errmsg("received smart shutdown request")));
-							current_time_as_str())));
 #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",
+					(errmsg("received fast shutdown request")));
-							current_time_as_str())));
 #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",
+					(errmsg("received immediate shutdown request")));
-							current_time_as_str())));
 #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);
 		}

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.

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;
 }
 

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)

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());
 }
 
 /*

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)
+		print_msg(_("waiting for server to shut down..."));
-		{
-			fprintf(stdout, _("waiting for server to shut down at %s..."),
-					current_time_as_str());
-			fflush(stdout);
-		}
 
 		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"),
+			write_stderr(_("%s: server does not shut down\n"), progname);
-						 progname, current_time_as_str());
 			if (shutdown_mode == SMART_MODE)
 				write_stderr(_("HINT: The \"-m fast\" option immediately disconnects sessions rather than\n"
 						  "waiting for session-initiated disconnection.\n"));

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);