Add still more chattiness in server shutdown.

Further investigation says that there may be some slow operations after
we've finished ShutdownXLOG(), so add some more log messages to try to
isolate that.  This is all temporary code too.

2 files changed, 31 insertions, 0 deletions

diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c
index 1337eabb3a5..a5fa1d4720a 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -2850,6 +2850,9 @@ 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);
@@ -3711,6 +3714,9 @@ 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/ipc/ipc.c b/src/backend/storage/ipc/ipc.c
index cc36b80699b..8db5f9ed326 100644
--- a/src/backend/storage/ipc/ipc.c
+++ b/src/backend/storage/ipc/ipc.c
@@ -98,6 +98,8 @@ 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);
 
@@ -140,6 +142,10 @@ 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);
 }
 
@@ -151,6 +157,8 @@ 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.
@@ -197,8 +205,13 @@ 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;
 }
@@ -214,6 +227,8 @@ proc_exit_prepare(int code)
 void
 shmem_exit(int code)
 {
+	bool noisy = AmCheckpointerProcess() || (getpid() == PostmasterPid);
+
 	/*
 	 * Call before_shmem_exit callbacks.
 	 *
@@ -225,8 +240,13 @@ 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;
 
 	/*
@@ -258,8 +278,13 @@ 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;
 }