From 5d6947f93d8126ca5b0a86d28a7cb2e57a252b0a Mon Sep 17 00:00:00 2001
From: Melanie Plageman <melanieplageman@gmail.com>
Date: Tue, 4 Mar 2025 09:44:34 -0500
Subject: [PATCH v9] Add connection establishment duration logging

Add log_connections option 'timings' which logs durations for several
key parts of connection establishment and setup when specified.

For a new 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. Provide visibility into
authentication and fork duration as well as the end-to-end connection
establishment and initialization time with logging.

To make this portable, the timings captured in the postmaster (socket
creation time, fork initiation time) are passed through the
BackendStartupData structures instead of simply saved in backend local
memory inherited by the child process.

Reviewed-by: Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
Reviewed-by: Fujii Masao <masao.fujii@oss.nttdata.com>
Reviewed-by: Jelte Fennema-Nio <postgres@jeltef.nl>
Reviewed-by: Jacob Champion <jacob.champion@enterprisedb.com>
Reviewed-by: Guillaume Lelarge <guillaume.lelarge@dalibo.com>
Discussion: https://postgr.es/m/flat/CAAKRu_b_smAHK0ZjrnL5GRxnAVWujEXQWpLXYzGbmpcZd3nLYw%40mail.gmail.com
---
 doc/src/sgml/config.sgml                | 17 +++++++----
 src/backend/libpq/auth.c                |  4 +--
 src/backend/postmaster/launch_backend.c | 38 +++++++++++++++++++++++++
 src/backend/postmaster/postmaster.c     |  8 +++++-
 src/backend/tcop/backend_startup.c      |  4 +--
 src/backend/tcop/postgres.c             | 21 ++++++++++++++
 src/backend/utils/init/globals.c        |  2 ++
 src/backend/utils/init/postinit.c       | 10 ++++++-
 src/backend/utils/misc/guc_tables.c     | 33 +++++++++++++++------
 src/include/miscadmin.h                 |  2 ++
 src/include/portability/instr_time.h    |  9 ++++++
 src/include/postmaster/postmaster.h     | 35 ++++++++++++++++++++++-
 src/include/tcop/backend_startup.h      | 12 ++++++++
 src/tools/pgindent/typedefs.list        |  2 ++
 14 files changed, 176 insertions(+), 21 deletions(-)

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index d2fa5f7d1a9..219c9ff6c5d 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -7315,20 +7315,27 @@ local0.*    /var/log/postgresql
      </varlistentry>
 
      <varlistentry id="guc-log-connections" xreflabel="log_connections">
-      <term><varname>log_connections</varname> (<type>boolean</type>)
+      <term><varname>log_connections</varname> (<type>enum</type>)
       <indexterm>
        <primary><varname>log_connections</varname> configuration parameter</primary>
       </indexterm>
       </term>
       <listitem>
        <para>
-        Causes each attempted connection to the server to be logged,
-        as well as successful completion of both client authentication (if
-        necessary) and authorization.
+        Causes each attempted connection to the server to be logged, as well as
+        successful completion of both client authentication (if necessary) and
+        authorization. Valid values are <literal>off</literal> (the default),
+        <literal>on</literal>, and <literal>timings</literal>.
+        <literal>timings</literal> emits all the messages emitted when
+        <structfield>log_connections</structfield> is <literal>on</literal>
+        plus an additional message at the end of connection setup containing
+        durations of various stages of connection establishment and setup.
+       </para>
+
+       <para>
         Only superusers and users with the appropriate <literal>SET</literal>
         privilege can change this parameter at session start,
         and it cannot be changed at all within a session.
-        The default is <literal>off</literal>.
        </para>
 
        <note>
diff --git a/src/backend/libpq/auth.c b/src/backend/libpq/auth.c
index 81e2f8184e3..041ef9ba2cf 100644
--- a/src/backend/libpq/auth.c
+++ b/src/backend/libpq/auth.c
@@ -349,7 +349,7 @@ set_authn_id(Port *port, const char *id)
 	MyClientConnectionInfo.authn_id = MemoryContextStrdup(TopMemoryContext, id);
 	MyClientConnectionInfo.auth_method = port->hba->auth_method;
 
-	if (Log_connections)
+	if (log_connections & LOG_CONNECTION_BASIC)
 	{
 		ereport(LOG,
 				errmsg("connection authenticated: identity=\"%s\" method=%s "
@@ -633,7 +633,7 @@ ClientAuthentication(Port *port)
 #endif
 	}
 
-	if (Log_connections && status == STATUS_OK &&
+	if (log_connections & LOG_CONNECTION_BASIC && status == STATUS_OK &&
 		!MyClientConnectionInfo.authn_id)
 	{
 		/*
diff --git a/src/backend/postmaster/launch_backend.c b/src/backend/postmaster/launch_backend.c
index 47375e5bfaa..2c45cbeb6d5 100644
--- a/src/backend/postmaster/launch_backend.c
+++ b/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 fork for logging */
+	if (child_type == B_BACKEND || child_type == B_WAL_SENDER)
+		INSTR_TIME_SET_CURRENT(((BackendStartupData *) startup_data)->fork_started);
+
 #ifdef EXEC_BACKEND
 	pid = internal_forkexec(child_process_kinds[child_type].name, child_slot,
 							startup_data, startup_data_len, client_sock);
@@ -240,6 +244,21 @@ postmaster_child_launch(BackendType child_type, int child_slot,
 	pid = fork_process();
 	if (pid == 0)				/* child */
 	{
+		/*
+		 * Transfer over any log_connections 'timings' data we need that was
+		 * collected by the postmaster. We save the time the socket was
+		 * created to later log the total connection establishment and setup
+		 * time. Calculate the total fork duration now since we have the start
+		 * and end times.
+		 */
+		if (child_type == B_BACKEND || child_type == B_WAL_SENDER)
+		{
+			BackendStartupData *data = (BackendStartupData *) startup_data;
+
+			conn_timing.fork_duration = INSTR_TIME_GET_DURATION_SINCE(data->fork_started);
+			conn_timing.creation_time = data->socket_created;
+		}
+
 		/* Close the postmaster's sockets */
 		ClosePostmasterPorts(child_type == B_LOGGER);
 
@@ -586,6 +605,7 @@ SubPostmasterMain(int argc, char *argv[])
 	char	   *child_kind;
 	BackendType child_type;
 	bool		found = false;
+	instr_time	fork_ended;
 
 	/* In EXEC_BACKEND case we will not have inherited these settings */
 	IsPostmasterEnvironment = true;
@@ -615,6 +635,9 @@ SubPostmasterMain(int argc, char *argv[])
 	if (!found)
 		elog(ERROR, "unknown child kind %s", child_kind);
 
+	if (child_type == B_BACKEND || child_type == B_WAL_SENDER)
+		INSTR_TIME_SET_CURRENT(fork_ended);
+
 	/* Read in the variables file */
 	read_backend_variables(argv[2], &startup_data, &startup_data_len);
 
@@ -648,6 +671,21 @@ SubPostmasterMain(int argc, char *argv[])
 	/* Read in remaining GUC variables */
 	read_nondefault_variables();
 
+	/*
+	 * Transfer over any log_connections 'timings' data we need that was
+	 * collected by the postmaster. We save the time the socket was created to
+	 * later log the total connection establishment and setup time. Calculate
+	 * the total fork duration now since we have the start and end times.
+	 */
+	if (child_type == B_BACKEND || child_type == B_WAL_SENDER)
+	{
+		BackendStartupData *data = (BackendStartupData *) startup_data;
+
+		conn_timing.fork_duration = fork_ended;
+		INSTR_TIME_SUBTRACT(conn_timing.fork_duration, data->fork_started);
+		conn_timing.creation_time = data->socket_created;
+	}
+
 	/*
 	 * Check that the data directory looks valid, which will also check the
 	 * privileges on the data directory and update our umask and file/group
diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c
index 5dd3b6a4fd4..68bc5e1f49e 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -237,7 +237,7 @@ int			PreAuthDelay = 0;
 int			AuthenticationTimeout = 60;
 
 bool		log_hostname;		/* for ps display and logging */
-bool		Log_connections = false;
+int			log_connections = 0;
 
 bool		enable_bonjour = false;
 char	   *bonjour_name;
@@ -3478,6 +3478,12 @@ BackendStartup(ClientSocket *client_sock)
 	BackendStartupData startup_data;
 	CAC_state	cac;
 
+	/*
+	 * Capture time that Postmaster got a socket from accept (for logging
+	 * connection establishment duration).
+	 */
+	INSTR_TIME_SET_CURRENT(startup_data.socket_created);
+
 	/*
 	 * 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
diff --git a/src/backend/tcop/backend_startup.c b/src/backend/tcop/backend_startup.c
index c70746fa562..da7f80c9337 100644
--- a/src/backend/tcop/backend_startup.c
+++ b/src/backend/tcop/backend_startup.c
@@ -201,8 +201,8 @@ BackendInitialize(ClientSocket *client_sock, CAC_state cac)
 	port->remote_host = MemoryContextStrdup(TopMemoryContext, remote_host);
 	port->remote_port = MemoryContextStrdup(TopMemoryContext, remote_port);
 
-	/* And now we can issue the Log_connections message, if wanted */
-	if (Log_connections)
+	/* And now we can log that the connection was received, if enabled */
+	if (log_connections & LOG_CONNECTION_BASIC)
 	{
 		if (remote_port[0])
 			ereport(LOG,
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index f2f75aa0f88..7bdd1f708fa 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -4153,6 +4153,7 @@ PostgresMain(const char *dbname, const char *username)
 	volatile bool send_ready_for_query = true;
 	volatile bool idle_in_transaction_timeout_enabled = false;
 	volatile bool idle_session_timeout_enabled = false;
+	bool		reported_first_ready_for_query = false;
 
 	Assert(dbname != NULL);
 	Assert(username != NULL);
@@ -4607,6 +4608,26 @@ 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.
+			 */
+			if (!reported_first_ready_for_query &&
+				log_connections & LOG_CONNECTION_TIMINGS &&
+				(AmRegularBackendProcess() || AmWalSenderProcess()))
+			{
+				instr_time	total_duration =
+					INSTR_TIME_GET_DURATION_SINCE(conn_timing.creation_time);
+
+				ereport(LOG,
+						errmsg("connection establishment times (ms): total: %ld, fork: %ld, authentication: %ld",
+							   (long int) INSTR_TIME_GET_MILLISEC(total_duration),
+							   (long int) INSTR_TIME_GET_MILLISEC(conn_timing.fork_duration),
+							   (long int) INSTR_TIME_GET_MILLISEC(conn_timing.auth_duration)));
+
+				reported_first_ready_for_query = true;
+			}
 			ReadyForQuery(whereToSendOutput);
 			send_ready_for_query = false;
 		}
diff --git a/src/backend/utils/init/globals.c b/src/backend/utils/init/globals.c
index b844f9fdaef..3c7b14dd57d 100644
--- a/src/backend/utils/init/globals.c
+++ b/src/backend/utils/init/globals.c
@@ -43,6 +43,8 @@ volatile uint32 InterruptHoldoffCount = 0;
 volatile uint32 QueryCancelHoldoffCount = 0;
 volatile uint32 CritSectionCount = 0;
 
+ConnectionTiming conn_timing = {0};
+
 int			MyProcPid;
 pg_time_t	MyStartTime;
 TimestampTz MyStartTimestamp;
diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
index ee1a9d5d98b..ad1437bb286 100644
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -191,9 +191,14 @@ GetDatabaseTupleByOid(Oid dboid)
 static void
 PerformAuthentication(Port *port)
 {
+	instr_time	auth_start_time;
+
 	/* This should be set already, but let's make sure */
 	ClientAuthInProgress = true;	/* limit visibility of log messages */
 
+	/* Capture authentication start time for logging */
+	INSTR_TIME_SET_CURRENT(auth_start_time);
+
 	/*
 	 * In EXEC_BACKEND case, we didn't inherit the contents of pg_hba.conf
 	 * etcetera from the postmaster, and have to load them ourselves.
@@ -252,7 +257,10 @@ PerformAuthentication(Port *port)
 	 */
 	disable_timeout(STATEMENT_TIMEOUT, false);
 
-	if (Log_connections)
+	/* Calculate authentication duration for logging */
+	conn_timing.auth_duration = INSTR_TIME_GET_DURATION_SINCE(auth_start_time);
+
+	if (log_connections & LOG_CONNECTION_BASIC)
 	{
 		StringInfoData logmsg;
 
diff --git a/src/backend/utils/misc/guc_tables.c b/src/backend/utils/misc/guc_tables.c
index ad25cbb39c5..a063cd10597 100644
--- a/src/backend/utils/misc/guc_tables.c
+++ b/src/backend/utils/misc/guc_tables.c
@@ -476,6 +476,20 @@ static const struct config_enum_entry wal_compression_options[] = {
 	{NULL, 0, false}
 };
 
+static const struct config_enum_entry log_connections_options[] = {
+	{"off", 0, false},
+	{"on", LOG_CONNECTION_BASIC, false},
+	{"true", LOG_CONNECTION_BASIC, true},
+	{"false", 0, true},
+	{"yes", LOG_CONNECTION_BASIC, true},
+	{"no", 0, true},
+	{"timings", LOG_CONNECTION_TIMINGS | LOG_CONNECTION_BASIC, false},
+	{"1", LOG_CONNECTION_BASIC, true},
+	{"0", 0, true},
+	{NULL, 0, false}
+};
+
+
 /*
  * Options for enum values stored in other modules
  */
@@ -1219,15 +1233,6 @@ struct config_bool ConfigureNamesBool[] =
 		true,
 		NULL, NULL, NULL
 	},
-	{
-		{"log_connections", PGC_SU_BACKEND, LOGGING_WHAT,
-			gettext_noop("Logs each successful connection."),
-			NULL
-		},
-		&Log_connections,
-		false,
-		NULL, NULL, NULL
-	},
 	{
 		{"trace_connection_negotiation", PGC_POSTMASTER, DEVELOPER_OPTIONS,
 			gettext_noop("Logs details of pre-authentication connection handshake."),
@@ -5299,6 +5304,16 @@ struct config_enum ConfigureNamesEnum[] =
 		NULL, NULL, NULL
 	},
 
+	{
+		{"log_connections", PGC_SU_BACKEND, LOGGING_WHAT,
+			gettext_noop("Logs information about events during connection establishment."),
+			NULL,
+		},
+		&log_connections,
+		0, log_connections_options,
+		NULL, NULL, NULL
+	},
+
 	/* End-of-list marker */
 	{
 		{NULL, 0, 0, NULL, NULL}, NULL, 0, NULL, NULL, NULL, NULL
diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h
index a2b63495eec..9dd18a2c74f 100644
--- a/src/include/miscadmin.h
+++ b/src/include/miscadmin.h
@@ -178,6 +178,8 @@ extern PGDLLIMPORT int MaxConnections;
 extern PGDLLIMPORT int max_worker_processes;
 extern PGDLLIMPORT int max_parallel_workers;
 
+extern PGDLLIMPORT struct ConnectionTiming conn_timing;
+
 extern PGDLLIMPORT int commit_timestamp_buffers;
 extern PGDLLIMPORT int multixact_member_buffers;
 extern PGDLLIMPORT int multixact_offset_buffers;
diff --git a/src/include/portability/instr_time.h b/src/include/portability/instr_time.h
index f71a851b18d..48d7ff1bfad 100644
--- a/src/include/portability/instr_time.h
+++ b/src/include/portability/instr_time.h
@@ -184,6 +184,15 @@ GetTimerFrequency(void)
 #define INSTR_TIME_ACCUM_DIFF(x,y,z) \
 	((x).ticks += (y).ticks - (z).ticks)
 
+static inline instr_time
+INSTR_TIME_GET_DURATION_SINCE(instr_time start_time)
+{
+	instr_time	now;
+
+	INSTR_TIME_SET_CURRENT(now);
+	INSTR_TIME_SUBTRACT(now, start_time);
+	return now;
+}
 
 #define INSTR_TIME_GET_DOUBLE(t) \
 	((double) INSTR_TIME_GET_NANOSEC(t) / NS_PER_S)
diff --git a/src/include/postmaster/postmaster.h b/src/include/postmaster/postmaster.h
index b6a3f275a1b..7ff3aa5179a 100644
--- a/src/include/postmaster/postmaster.h
+++ b/src/include/postmaster/postmaster.h
@@ -15,6 +15,7 @@
 
 #include "lib/ilist.h"
 #include "miscadmin.h"
+#include "portability/instr_time.h"
 
 /*
  * A struct representing an active postmaster child process.  This is used
@@ -51,6 +52,17 @@ typedef struct
 extern int	num_pmchild_slots;
 #endif
 
+
+/*
+ * Granular control over which messages to log for the log_connections GUC.
+ */
+typedef enum LogConnectionOption
+{
+	LOG_CONNECTION_BASIC = (1 << 0),
+	LOG_CONNECTION_TIMINGS = (1 << 1),
+} LogConnectionOption;
+
+
 /* GUC options */
 extern PGDLLIMPORT bool EnableSSL;
 extern PGDLLIMPORT int SuperuserReservedConnections;
@@ -63,7 +75,7 @@ extern PGDLLIMPORT char *ListenAddresses;
 extern PGDLLIMPORT bool ClientAuthInProgress;
 extern PGDLLIMPORT int PreAuthDelay;
 extern PGDLLIMPORT int AuthenticationTimeout;
-extern PGDLLIMPORT bool Log_connections;
+extern PGDLLIMPORT int log_connections;
 extern PGDLLIMPORT bool log_hostname;
 extern PGDLLIMPORT bool enable_bonjour;
 extern PGDLLIMPORT char *bonjour_name;
@@ -126,6 +138,27 @@ extern PMChild *AllocDeadEndChild(void);
 extern bool ReleasePostmasterChildSlot(PMChild *pmchild);
 extern PMChild *FindPostmasterChildByPid(int pid);
 
+/*
+ * A collection of timings and durations of various stages of connection
+ * establishment and setup for client backends and WAL senders. Used for
+ * log_connections 'timings' option.
+ */
+typedef struct ConnectionTiming
+{
+	/*
+	 * The time at which the client socket is created. This is used to log the
+	 * total connection establishment and setup time from accept() to first
+	 * being ready for query.
+	 */
+	instr_time	creation_time;
+
+	/* How long it took the backend to be forked. */
+	instr_time	fork_duration;
+
+	/* How long authentication took */
+	instr_time	auth_duration;
+} ConnectionTiming;
+
 /*
  * These values correspond to the special must-be-first options for dispatching
  * to various subprograms.  parse_dispatch_option() can be used to convert an
diff --git a/src/include/tcop/backend_startup.h b/src/include/tcop/backend_startup.h
index 73285611203..62b4746ee60 100644
--- a/src/include/tcop/backend_startup.h
+++ b/src/include/tcop/backend_startup.h
@@ -37,6 +37,18 @@ typedef enum CAC_state
 typedef struct BackendStartupData
 {
 	CAC_state	canAcceptConnections;
+
+	/*
+	 * Time at which the postmaster initiates a fork of a backend process.
+	 * Only used for client and wal sender connections.
+	 */
+	instr_time	fork_started;
+
+	/*
+	 * Time at which the connection client socket is created. Only used for
+	 * client and wal sender connections.
+	 */
+	instr_time	socket_created;
 } BackendStartupData;
 
 extern void BackendMain(const void *startup_data, size_t startup_data_len) pg_attribute_noreturn();
diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list
index 9840060997f..3da74999634 100644
--- a/src/tools/pgindent/typedefs.list
+++ b/src/tools/pgindent/typedefs.list
@@ -484,6 +484,7 @@ ConnParams
 ConnStatusType
 ConnType
 ConnectionStateEnum
+ConnectionTiming
 ConsiderSplitContext
 Const
 ConstrCheck
@@ -1555,6 +1556,7 @@ LockTupleMode
 LockViewRecurse_context
 LockWaitPolicy
 LockingClause
+LogConnectionOption
 LogOpts
 LogStmtLevel
 LogicalDecodeBeginCB
-- 
2.34.1

