Add connection establishment duration logging

Add log_connections option 'setup_durations' which logs durations of
several key parts of connection establishment and backend setup.

For an incoming connection, starting from when the postmaster gets a
socket from accept() and ending when the forked child backend is first
ready for query, there are multiple steps that could each take longer
than expected due to external factors. This logging provides visibility
into authentication and fork duration as well as the end-to-end
connection establishment and backend initialization time.

To make this portable, the timings captured in the postmaster (socket
creation time, fork initiation time) are passed through the
BackendStartupData.

Author: Melanie Plageman <melanieplageman@gmail.com>
Reviewed-by: Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
Reviewed-by: Fujii Masao <masao.fujii@oss.nttdata.com>
Reviewed-by: Daniel Gustafsson <daniel@yesql.se>
Reviewed-by: Jacob Champion <jacob.champion@enterprisedb.com>
Reviewed-by: Jelte Fennema-Nio <postgres@jeltef.nl>
Reviewed-by: Guillaume Lelarge <guillaume.lelarge@dalibo.com>
Discussion: https://postgr.es/m/flat/CAAKRu_b_smAHK0ZjrnL5GRxnAVWujEXQWpLXYzGbmpcZd3nLYw%40mail.gmail.com

src/backend/postmaster/launch_backend.c

@@ -232,6 +232,10 @@ postmaster_child_launch(BackendType child_type, int child_slot,
 
 	Assert(IsPostmasterEnvironment && !IsUnderPostmaster);
 
+	/* Capture time Postmaster initiates process creation for logging */
+	if (IsExternalConnectionBackend(child_type))
+		((BackendStartupData *) startup_data)->fork_started = GetCurrentTimestamp();
+
 #ifdef EXEC_BACKEND
 	pid = internal_forkexec(child_process_kinds[child_type].name, child_slot,
 							startup_data, startup_data_len, client_sock);
@@ -240,6 +244,16 @@ postmaster_child_launch(BackendType child_type, int child_slot,
 	pid = fork_process();
 	if (pid == 0)				/* child */
 	{
+		/* Capture and transfer timings that may be needed for logging */
+		if (IsExternalConnectionBackend(child_type))
+		{
+			conn_timing.socket_create =
+				((BackendStartupData *) startup_data)->socket_created;
+			conn_timing.fork_start =
+				((BackendStartupData *) startup_data)->fork_started;
+			conn_timing.fork_end = GetCurrentTimestamp();
+		}
+
 		/* Close the postmaster's sockets */
 		ClosePostmasterPorts(child_type == B_LOGGER);
 
@@ -586,11 +600,18 @@ SubPostmasterMain(int argc, char *argv[])
 	char	   *child_kind;
 	BackendType child_type;
 	bool		found = false;
+	TimestampTz fork_end;
 
 	/* In EXEC_BACKEND case we will not have inherited these settings */
 	IsPostmasterEnvironment = true;
 	whereToSendOutput = DestNone;
 
+	/*
+	 * Capture the end of process creation for logging. We don't include the
+	 * time spent copying data from shared memory and setting up the backend.
+	 */
+	fork_end = GetCurrentTimestamp();
+
 	/* Setup essential subsystems (to ensure elog() behaves sanely) */
 	InitializeGUCOptions();
 
@@ -648,6 +669,16 @@ SubPostmasterMain(int argc, char *argv[])
 	/* Read in remaining GUC variables */
 	read_nondefault_variables();
 
+	/* Capture and transfer timings that may be needed for log_connections */
+	if (IsExternalConnectionBackend(child_type))
+	{
+		conn_timing.socket_create =
+			((BackendStartupData *) startup_data)->socket_created;
+		conn_timing.fork_start =
+			((BackendStartupData *) startup_data)->fork_started;
+		conn_timing.fork_end = fork_end;
+	}
+
 	/*
 	 * Check that the data directory looks valid, which will also check the
 	 * privileges on the data directory and update our umask and file/group

src/backend/postmaster/postmaster.c

@@ -3477,6 +3477,12 @@ BackendStartup(ClientSocket *client_sock)
 	BackendStartupData startup_data;
 	CAC_state	cac;
 
+	/*
+	 * Capture time that Postmaster got a socket from accept (for logging
+	 * connection establishment and setup total duration).
+	 */
+	startup_data.socket_created = GetCurrentTimestamp();
+
 	/*
 	 * Allocate and assign the child slot.  Note we must do this before
 	 * forking, so that we can handle failures (out of memory or child-process

src/backend/tcop/backend_startup.c

@@ -46,6 +46,16 @@ bool		Trace_connection_negotiation = false;
 uint32		log_connections = 0;
 char	   *log_connections_string = NULL;
 
+/* Other globals */
+
+/*
+ * ConnectionTiming stores timestamps of various points in connection
+ * establishment and setup.
+ * ready_for_use is initialized to a special value here so we can check if
+ * we've already set it before doing so in PostgresMain().
+ */
+ConnectionTiming conn_timing = {.ready_for_use = TIMESTAMP_MINUS_INFINITY};
+
 static void BackendInitialize(ClientSocket *client_sock, CAC_state cac);
 static int	ProcessSSLStartup(Port *port);
 static int	ProcessStartupPacket(Port *port, bool ssl_done, bool gss_done);
@@ -1006,6 +1016,7 @@ validate_log_connections_options(List *elemlist, uint32 *flags)
 			{"receipt", LOG_CONNECTION_RECEIPT},
 			{"authentication", LOG_CONNECTION_AUTHENTICATION},
 			{"authorization", LOG_CONNECTION_AUTHORIZATION},
+			{"setup_durations", LOG_CONNECTION_SETUP_DURATIONS},
 			{"all", LOG_CONNECTION_ALL},
 		};
 

src/backend/tcop/postgres.c

@@ -66,6 +66,7 @@
 #include "storage/proc.h"
 #include "storage/procsignal.h"
 #include "storage/sinval.h"
+#include "tcop/backend_startup.h"
 #include "tcop/fastpath.h"
 #include "tcop/pquery.h"
 #include "tcop/tcopprot.h"
@@ -4607,6 +4608,38 @@ PostgresMain(const char *dbname, const char *username)
 			/* Report any recently-changed GUC options */
 			ReportChangedGUCOptions();
 
+			/*
+			 * The first time this backend is ready for query, log the
+			 * durations of the different components of connection
+			 * establishment and setup.
+			 */
+			if (conn_timing.ready_for_use == TIMESTAMP_MINUS_INFINITY &&
+				(log_connections & LOG_CONNECTION_SETUP_DURATIONS) &&
+				IsExternalConnectionBackend(MyBackendType))
+			{
+				uint64		total_duration,
+							fork_duration,
+							auth_duration;
+
+				conn_timing.ready_for_use = GetCurrentTimestamp();
+
+				total_duration =
+					TimestampDifferenceMicroseconds(conn_timing.socket_create,
+													conn_timing.ready_for_use);
+				fork_duration =
+					TimestampDifferenceMicroseconds(conn_timing.fork_start,
+													conn_timing.fork_end);
+				auth_duration =
+					TimestampDifferenceMicroseconds(conn_timing.auth_start,
+													conn_timing.auth_end);
+
+				ereport(LOG,
+						errmsg("connection ready: setup total=%.3f ms, fork=%.3f ms, authentication=%.3f ms",
+							   (double) total_duration / NS_PER_US,
+							   (double) fork_duration / NS_PER_US,
+							   (double) auth_duration / NS_PER_US));
+			}
+
 			ReadyForQuery(whereToSendOutput);
 			send_ready_for_query = false;
 		}

src/backend/utils/init/postinit.c

@@ -235,6 +235,9 @@ PerformAuthentication(Port *port)
 	}
 #endif
 
+	/* Capture authentication start time for logging */
+	conn_timing.auth_start = GetCurrentTimestamp();
+
 	/*
 	 * Set up a timeout in case a buggy or malicious client fails to respond
 	 * during authentication.  Since we're inside a transaction and might do
@@ -253,6 +256,9 @@ PerformAuthentication(Port *port)
 	 */
 	disable_timeout(STATEMENT_TIMEOUT, false);
 
+	/* Capture authentication end time for logging */
+	conn_timing.auth_end = GetCurrentTimestamp();
+
 	if (log_connections & LOG_CONNECTION_AUTHORIZATION)
 	{
 		StringInfoData logmsg;

src/backend/utils/misc/postgresql.conf.sample

@@ -580,7 +580,7 @@
 #log_checkpoints = on
 #log_connections = '' # log aspects of connection setup
           # options include receipt, authentication, authorization,
-          # and all to log all of these aspects
+          # setup_durations, and all to log all of these aspects
 #log_disconnections = off
 #log_duration = off # log statement duration
 #log_error_verbosity = default		# terse, default, or verbose messages