From 743d488161758ff923573cc65f3ac437feafd738 Mon Sep 17 00:00:00 2001
From: Melanie Plageman <melanieplageman@gmail.com>
Date: Tue, 25 Feb 2025 13:08:48 -0500
Subject: [PATCH v5] Add connection establishment duration logging

Add durations for several key parts of connection establishment when
log_connections is enabled.

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 time with logging.

To make this portable, the timestamps captured in the postmaster (socket
creation time, fork initiation time) are passed through the ClientSocket
and 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
---
 src/backend/postmaster/launch_backend.c | 23 +++++++++++++++++++++++
 src/backend/postmaster/postmaster.c     |  8 ++++++++
 src/backend/tcop/postgres.c             | 21 +++++++++++++++++++++
 src/backend/utils/init/globals.c        |  2 ++
 src/backend/utils/init/postinit.c       | 12 ++++++++++++
 src/include/libpq/libpq-be.h            |  2 ++
 src/include/miscadmin.h                 |  2 ++
 src/include/portability/instr_time.h    |  9 +++++++++
 src/include/postmaster/postmaster.h     |  7 +++++++
 src/include/tcop/backend_startup.h      |  5 +++++
 src/tools/pgindent/typedefs.list        |  1 +
 11 files changed, 92 insertions(+)

diff --git a/src/backend/postmaster/launch_backend.c b/src/backend/postmaster/launch_backend.c
index 47375e5bfaa..c482cb299f7 100644
--- a/src/backend/postmaster/launch_backend.c
+++ b/src/backend/postmaster/launch_backend.c
@@ -232,6 +232,11 @@ postmaster_child_launch(BackendType child_type, int child_slot,
 
 	Assert(IsPostmasterEnvironment && !IsUnderPostmaster);
 
+	/* Capture time Postmaster initiates fork for logging */
+	if (Log_connections &&
+		(child_type == B_BACKEND || child_type == B_WAL_SENDER))
+		INSTR_TIME_SET_CURRENT(((BackendStartupData *) startup_data)->fork_time);
+
 #ifdef EXEC_BACKEND
 	pid = internal_forkexec(child_process_kinds[child_type].name, child_slot,
 							startup_data, startup_data_len, client_sock);
@@ -240,6 +245,15 @@ postmaster_child_launch(BackendType child_type, int child_slot,
 	pid = fork_process();
 	if (pid == 0)				/* child */
 	{
+		/* Calculate total fork duration in child backend for logging */
+		if (Log_connections &&
+			(child_type == B_BACKEND || child_type == B_WAL_SENDER))
+		{
+			instr_time	fork_time = ((BackendStartupData *) startup_data)->fork_time;
+
+			conn_timing.fork_duration = INSTR_TIME_GET_DURATION_SINCE(fork_time);
+		}
+
 		/* Close the postmaster's sockets */
 		ClosePostmasterPorts(child_type == B_LOGGER);
 
@@ -618,6 +632,15 @@ SubPostmasterMain(int argc, char *argv[])
 	/* Read in the variables file */
 	read_backend_variables(argv[2], &startup_data, &startup_data_len);
 
+	/* Calculate total fork duration in child backend for logging */
+	if (Log_connections &&
+		(child_type == B_BACKEND || child_type == B_WAL_SENDER))
+	{
+		instr_time	fork_time = ((BackendStartupData *) startup_data)->fork_time;
+
+		conn_timing.fork_duration = INSTR_TIME_GET_DURATION_SINCE(fork_time);
+	}
+
 	/* Close the postmaster's sockets (as soon as we know them) */
 	ClosePostmasterPorts(child_type == B_LOGGER);
 
diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c
index 5dd3b6a4fd4..880f491a9f7 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -1685,7 +1685,14 @@ ServerLoop(void)
 				ClientSocket s;
 
 				if (AcceptConnection(events[i].fd, &s) == STATUS_OK)
+				{
+					/*
+					 * Capture time that Postmaster got a socket from accept
+					 * (for logging connection establishment duration)
+					 */
+					INSTR_TIME_SET_CURRENT(s.creation_time);
 					BackendStartup(&s);
+				}
 
 				/* We no longer need the open socket in this process */
 				if (s.sock != PGINVALID_SOCKET)
@@ -3511,6 +3518,7 @@ BackendStartup(ClientSocket *client_sock)
 
 	/* Pass down canAcceptConnections state */
 	startup_data.canAcceptConnections = cac;
+	INSTR_TIME_SET_ZERO(startup_data.fork_time);
 	bn->rw = NULL;
 
 	/* Hasn't asked to be notified about any bgworkers yet */
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index f2f75aa0f88..61d4ae2474d 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 &&
+				(AmRegularBackendProcess() || AmWalSenderProcess()))
+			{
+				instr_time	total_duration =
+					INSTR_TIME_GET_DURATION_SINCE(MyClientSocket->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 318600d6d02..30eed2e85f7 100644
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -190,9 +190,16 @@ 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 */
+	if (Log_connections &&
+		(AmRegularBackendProcess() || AmWalSenderProcess()))
+		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.
@@ -251,6 +258,11 @@ PerformAuthentication(Port *port)
 	 */
 	disable_timeout(STATEMENT_TIMEOUT, false);
 
+	/* Calculate authentication duration for logging */
+	if (Log_connections &&
+		(AmRegularBackendProcess() || AmWalSenderProcess()))
+		conn_timing.auth_duration = INSTR_TIME_GET_DURATION_SINCE(auth_start_time);
+
 	if (Log_connections)
 	{
 		StringInfoData logmsg;
diff --git a/src/include/libpq/libpq-be.h b/src/include/libpq/libpq-be.h
index 7fe92b15477..b16ad69efff 100644
--- a/src/include/libpq/libpq-be.h
+++ b/src/include/libpq/libpq-be.h
@@ -58,6 +58,7 @@ typedef struct
 #include "datatype/timestamp.h"
 #include "libpq/hba.h"
 #include "libpq/pqcomm.h"
+#include "portability/instr_time.h"
 
 
 /*
@@ -252,6 +253,7 @@ typedef struct ClientSocket
 {
 	pgsocket	sock;			/* File descriptor */
 	SockAddr	raddr;			/* remote addr (client) */
+	instr_time	creation_time;
 } ClientSocket;
 
 #ifdef USE_SSL
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..71a3f5f644d 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
@@ -126,6 +127,12 @@ extern PMChild *AllocDeadEndChild(void);
 extern bool ReleasePostmasterChildSlot(PMChild *pmchild);
 extern PMChild *FindPostmasterChildByPid(int pid);
 
+typedef struct ConnectionTiming
+{
+	instr_time	fork_duration;
+	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..7d9c43ce77b 100644
--- a/src/include/tcop/backend_startup.h
+++ b/src/include/tcop/backend_startup.h
@@ -14,6 +14,8 @@
 #ifndef BACKEND_STARTUP_H
 #define BACKEND_STARTUP_H
 
+#include "portability/instr_time.h"
+
 /* GUCs */
 extern PGDLLIMPORT bool Trace_connection_negotiation;
 
@@ -37,6 +39,9 @@ typedef enum CAC_state
 typedef struct BackendStartupData
 {
 	CAC_state	canAcceptConnections;
+
+	/* Time at which the postmaster initiates a fork of a backend process */
+	instr_time	fork_time;
 } 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 cfbab589d61..566b0d8d73b 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
-- 
2.34.1

