Subject: Re: Log connection establishment timings

From: Melanie Plageman <[email-masked]>
Date: Tue, 25 Feb 2025 15:23:31 -0500

Thanks for taking a look!

On Mon, Jan 20, 2025 at 10:01 AM Bertrand Drouvot
<[email-masked]> wrote:
>
> The patch needed a rebase due to 34486b6092e. I did it in v2 attached (it's
> a minor rebase due to the AmRegularBackendProcess() introduction in miscadmin.h).
>
> v2 could rely on AmRegularBackendProcess() instead of AmClientBackendProcess()
> but I kept it with AmClientBackendProcess() to reduce "my" changes as compared to
> v1.

Thanks for doing this! I have implemented your suggestion in attached v3.

> Regarding the TimestampTz vs instr_time choice, we have things like:
< -- snip -- >
> So with TimestampTz, we would:
>
> 1. return 0 if we moved the time backward
> 2. provide an inflated duration including the time jump (if the time move
> forward).
>
> But with instr_time (and on systems that support CLOCK_MONOTONIC) then
> pg_clock_gettime_ns() should not be affected by system time change IIUC.
>
> Though time changes are "rare", given the fact that those metrics could provide
> "inaccurate" measurements during that particular moment (time change) then it
> might be worth considering instr_time instead for this particular metric.

Great point. This all makes sense. I've switched to using instr_time in v3.

- Melanie
From 660e2f3846fd1af74956a45559da5ea17d5dbc92 Mon Sep 17 00:00:00 2001
From: Melanie Plageman <[email-masked]>
Date: Tue, 25 Feb 2025 13:08:48 -0500
Subject: [PATCH v3] Add connection establishment duration logging

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

For a new incoming conneciton, 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 <[email-masked]>
Reviewed-by: Jelte Fennema-Nio <[email-masked]>
Reviewed-by: Jacob Champion <[email-masked]>
Discussion: https://postgr.es/m/flat/CAAKRu_b_smAHK0ZjrnL5GRxnAVWujEXQWpLXYzGbmpcZd3nLYw%40mail.gmail.com
---
 src/backend/postmaster/launch_backend.c | 20 ++++++++++++++++++++
 src/backend/postmaster/postmaster.c     |  8 ++++++++
 src/backend/tcop/postgres.c             | 24 ++++++++++++++++++++++++
 src/backend/utils/init/globals.c        |  2 ++
 src/backend/utils/init/postinit.c       | 13 +++++++++++++
 src/include/libpq/libpq-be.h            |  2 ++
 src/include/miscadmin.h                 |  2 ++
 src/include/postmaster/postmaster.h     |  7 +++++++
 src/include/tcop/backend_startup.h      |  1 +
 src/tools/pgindent/typedefs.list        |  1 +
 10 files changed, 80 insertions(+)

diff --git a/src/backend/postmaster/launch_backend.c b/src/backend/postmaster/launch_backend.c
index 47375e5bfaa..37b31069120 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)
+		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 +244,14 @@ 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 (child_type == B_BACKEND)
+		{
+			INSTR_TIME_SET_CURRENT(conn_timing.fork_duration);
+			INSTR_TIME_SUBTRACT(conn_timing.fork_duration,
+								((BackendStartupData *) startup_data)->fork_time);
+		}
+
 		/* Close the postmaster's sockets */
 		ClosePostmasterPorts(child_type == B_LOGGER);
 
@@ -618,6 +630,14 @@ 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 (child_type == B_BACKEND)
+	{
+		INSTR_TIME_SET_CURRENT(conn_timing.fork_duration);
+		INSTR_TIME_SUBTRACT(conn_timing.fork_duration,
+				((BackendStartupData *) startup_data)->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..abd7e648657 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,29 @@ 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())
+			{
+				instr_time	total_duration;
+
+				INSTR_TIME_SET_CURRENT(total_duration);
+				INSTR_TIME_SUBTRACT(total_duration, MyClientSocket->creation_time);
+
+				ereport(LOG,
+						errmsg("backend ready for query. pid=%d. socket=%d. connection establishment times (ms): total: %ld, fork: %ld, authentication: %ld",
+							   MyProcPid,
+							   (int) MyClientSocket->sock,
+							   (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..c262849b9ac 100644
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -190,9 +190,15 @@ 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 (AmRegularBackendProcess())
+		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 +257,13 @@ PerformAuthentication(Port *port)
 	 */
 	disable_timeout(STATEMENT_TIMEOUT, false);
 
+	/* Calculate authentication duration for logging */
+	if (AmRegularBackendProcess())
+	{
+		INSTR_TIME_SET_CURRENT(conn_timing.auth_duration);
+		INSTR_TIME_SUBTRACT(conn_timing.auth_duration, 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/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..d5d13bf140a 100644
--- a/src/include/tcop/backend_startup.h
+++ b/src/include/tcop/backend_startup.h
@@ -37,6 +37,7 @@ typedef enum CAC_state
 typedef struct BackendStartupData
 {
 	CAC_state	canAcceptConnections;
+	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 1649f5e1011..34d2daa0c9b 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

---

From: Melanie Plageman <[email-masked]>
Date: Tue, 25 Feb 2025 16:36:44 -0500

> Thanks for doing this! I have implemented your suggestion in attached v3.

I missed an include in the EXEC_BACKEND not defined case. attached v4
is fixed up.

- Melanie
From c493f0be7243bfe965d3493f07982ea1072d89b7 Mon Sep 17 00:00:00 2001
From: Melanie Plageman <[email-masked]>
Date: Tue, 25 Feb 2025 13:08:48 -0500
Subject: [PATCH v4] Add connection establishment duration logging

 src/include/tcop/backend_startup.h      |  3 +++
 10 files changed, 82 insertions(+)

 

 

 

 	Assert(dbname != NULL);
 
+			/*

 

 /*
 
 #ifdef USE_SSL

 #include "lib/ilist.h"
 #include "miscadmin.h"
 
 /*
 
+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..deb59c78425 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,7 @@ typedef enum CAC_state
 typedef struct BackendStartupData
 {
 	CAC_state	canAcceptConnections;
+	instr_time	fork_time;
 } BackendStartupData;

---

From: Fujii Masao <[email-masked]>
Date: Wed, 26 Feb 2025 13:46:19 +0900

> I missed an include in the EXEC_BACKEND not defined case. attached v4

Thanks for updating the patch!

When log_connections is enabled, walsender connections are also logged.
However, with the patch, it seems the connection time for walsenders isn't captured.
Is this intentional?

With the current patch, when log_connections is enabled, the connection time is always
captured, and which might introduce performance overhead. No? Some users who enable
log_connections may not want this extra detail and want to avoid such overhead.
So, would it make sense to extend log_connections with a new option like "timing" and
log the connection time only when "timing" is specified?

+				ereport(LOG,

Why expose the socket's file descriptor? I'm not sure how users would use that information.

Including the PID seems unnecessary since it's already available via log_line_prefix with %p?

Regards,

-- 
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION

---

From: Bertrand Drouvot <[email-masked]>
Date: Wed, 26 Feb 2025 07:41:57 +0000

Hi,

> > > Thanks for doing this! I have implemented your suggestion in attached v3.

Thanks for the new patch version!

> However, with the patch, it seems the connection time for walsenders isn't captured.

Good point. I'm tempted to say that it should also be, specially because a
connection done as "psql replication=database" is of "walsender" backend type and
would not be reported.

> log the connection time only when "timing" is specified?

+1, I also think it's a good idea to let users decide if they want the timing
measurement overhead (and it's common practice with track_io_timing,
track_wal_io_timing, the newly track_cost_delay_timing for example)

> Including the PID seems unnecessary since it's already available via log_line_prefix with %p?

Yeah, we would get things like:

[1111539] LOG:  connection received: host=[local]
[1111539] LOG:  connection authenticated: user="postgres" method=trust (/home/postgres/postgresql/pg_installed/pg18/data/pg_hba.conf:117)
[1111539] LOG:  connection authorized: user=postgres database=postgres application_name=psql
[1111539] LOG:  backend ready for query. pid=1111539. socket=9. connection establishment times (ms): total: 2, fork: 0, authentication: 0

I also wonder if "backend ready for query" is worth it. Maybe something like:

2025-02-26 06:44:23.265 UTC [1111539] LOG:  connection establishment times (ms): total: 2, fork: 0, authentication: 0

would be good enough?

A few random comments:

=== 1

As it's all about instr_time, I wonder if we could use an enum + array instead.
That's probably just a matter of taste but that sounds more flexible to extend
(should we want to add more timing in the future).

=== 2

There is no padding in ConnectionTiming and anyway we just access its fields
so that's ok to initialize that way.

=== 3

Add a few words in the log_connections GUC doc? (anyway we will have to if
Fujii-san idea above about the timing is implemented)

=== 4

worth to add a helper function to avoid code duplication?

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com

---

From: Guillaume Lelarge <[email-masked]>
Date: Wed, 26 Feb 2025 14:22:32 +0100

> Thanks for the new patch version!

+1

> connection done as "psql replication=database" is of "walsender" backend type and

Agreed.

> track_wal_io_timing, the newly track_cost_delay_timing for example)

track_connection_delay_timing ? I'm fine with this, but I'm a bit afraid 
that it will lead us to an awful lot of GUCs for simple things.

> 2025-02-26 06:44:23.265 UTC [1111539] LOG:  connection establishment times (ms): total: 2, fork: 0, authentication: 0

Sounds definitely better to me.

-- 
Guillaume Lelarge
Consultant
https://dalibo.com

---

From: Melanie Plageman <[email-masked]>
Date: Wed, 26 Feb 2025 13:37:40 -0500

Thanks for the review!

> However, with the patch, it seems the connection time for walsenders isn't captured.

Ah, great point. It was not intentional. I've added a check for wal
sender to the attached v5.
Are these the only backend types that establish connections from outside?

This makes me wonder if I don't need these checks (for backend type)
before capturing the current time in PerformAuthentication() -- that
is, if they are performing authentication, aren't they inherently one
of these backend types?

> log the connection time only when "timing" is specified?

Ah yes, I did this intentionally originally because I thought someone
might change the value of log_connections in between the start and end
of the duration. I now see you cannot change log_connections after
connection start. So, I can guard these behind log_connections (done
in attached v5).

I hesitate to have a separate guc controlling whether or not we log
connection timing. If we add far more instances of getting the current
time, then perhaps it makes sense. But, as it is, we are adding six
system calls that take on the order of nanoseconds (esp if using
clock_gettime()), whereas emitting each log message -- which
log_connections allows -- will take on the order of micro or even
milliseconds.

> Why expose the socket's file descriptor? I'm not sure how users would use that information.

I originally included the socket fd because I thought we might end up
printing the times instead of the durations and then users would have
to parse them to get the durations and would need a way to uniquely
identify a connection. This would ideally be a combination of client
address, client port, server address, server port -- but those are
harder to print out (due to IP versions, etc) and harder to parse.

Also, I did notice other places printing the socket (like
BackendStartup() after forking).

Since this version is just printing one message, I have removed the socket fd.

> Including the PID seems unnecessary since it's already available via log_line_prefix with %p?

Ah, great point. I've removed that from the log message in the attached version

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

For a new incoming connection, starting from when the postmaster gets a

Reviewed-by: Bertrand Drouvot <[email-masked]>
Reviewed-by: Fujii Masao <[email-masked]>
Reviewed-by: Jelte Fennema-Nio <[email-masked]>
Reviewed-by: Jacob Champion <[email-masked]>
Reviewed-by: Guillaume Lelarge <[email-masked]>
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,

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

 

index f2f75aa0f88..61d4ae2474d 100644
 
 	Assert(dbname != NULL);
 	Assert(username != NULL);
@@ -4607,6 +4608,26 @@ PostgresMain(const char *dbname, const char *username)
 			/* Report any recently-changed GUC options */
 			ReportChangedGUCOptions();
 
+			/*
+				Log_connections &&
+				(AmRegularBackendProcess() || AmWalSenderProcess()))
+				instr_time	total_duration =
+					INSTR_TIME_GET_DURATION_SINCE(MyClientSocket->creation_time);
+						errmsg("connection establishment times (ms): total: %ld, fork: %ld, authentication: %ld",
 
index 318600d6d02..30eed2e85f7 100644
@@ -190,9 +190,16 @@ GetDatabaseTupleByOid(Oid dboid)
 
+	/* 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);
 
+	if (Log_connections &&
+		(AmRegularBackendProcess() || AmWalSenderProcess()))
+		conn_timing.auth_duration = INSTR_TIME_GET_DURATION_SINCE(auth_start_time);

 /*
 
 #ifdef USE_SSL
 
+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"
 
 /*
 
index 73285611203..7d9c43ce77b 100644

@@ -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;
 
index cfbab589d61..566b0d8d73b 100644

---

From: Melanie Plageman <[email-masked]>
Date: Wed, 26 Feb 2025 13:45:39 -0500

Thanks for the continued review!

> track_wal_io_timing, the newly track_cost_delay_timing for example)

It seems to me like the extra timing collected and the one additional
log message isn't enough overhead to justify its own guc (for now).

> 2025-02-26 06:44:23.265 UTC [1111539] LOG:  connection establishment times (ms): total: 2, fork: 0, authentication: 0

Yes, thank you. v5 attached in [1] changes the wording as you recommend..

> (should we want to add more timing in the future).

I think we can change it later if we add many more. For now I prefer
the clarity of accessing members by name. Especially because we don't
have any code yet that loops through all of them or anything like
that.

> so that's ok to initialize that way.

Yes, this properly zero initializes the struct. In fact it shouldn't
be needed since a global like this should be zero initialized. But all
of the globals defined above conn_timing zero initialize themselves,
so I thought I would be consistent with them.

> Fujii-san idea above about the timing is implemented)

I forgot to do this in v5 attached in [1]. Let me go ahead and do this next.

> worth to add a helper function to avoid code duplication?

I've added INSTR_TIME_GET_DURATION_SINCE(start_time). Which I like
because it seems generally useful. It does not however cut down on
LOC, so I'm somewhat on the fence.

- Melanie

[1] https://www.postgresql.org/message-id/CAAKRu_Y9sgZAWCiQoHtpwx6Mv28fBGav5ztrWyeSrx%2BB%3DACN6g%40mail.gmail.com

---

From: Melanie Plageman <[email-masked]>
Date: Wed, 26 Feb 2025 14:29:33 -0500

> I forgot to do this in v5 attached in [1]. Let me go ahead and do this next.

I took a stab at this in attached v6. I feel that what I have is a bit
stilted, but I'm not sure how to fix it.

- Melanie
From 990f6841c3a6795d315821278d985cf0c5632f5e Mon Sep 17 00:00:00 2001
From: Melanie Plageman <[email-masked]>
Date: Tue, 25 Feb 2025 13:08:48 -0500
Subject: [PATCH v6] Add connection establishment duration logging

ci-os-only:
---
 doc/src/sgml/config.sgml                |  1 +
 12 files changed, 93 insertions(+)

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index e55700f35b8..4861796654b 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -7325,6 +7325,7 @@ local0.*    /var/log/postgresql
         Causes each attempted connection to the server to be logged,
         as well as successful completion of both client authentication (if
         necessary) and authorization.
+        Successful connections log the connection establishment duration.
         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.
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(dbname != NULL);
 
+			/*

 

 /*
 
 #ifdef USE_SSL

 
 
 #include "lib/ilist.h"
 #include "miscadmin.h"
 
 /*

---

From: Bertrand Drouvot <[email-masked]>
Date: Thu, 27 Feb 2025 06:50:41 +0000

Hi,

> log message isn't enough overhead to justify its own guc (for now).

Agree. IIUC, I think that Fujii-san's idea was to extend log_connections with
a new option "timing" (i.e move it from ConfigureNamesBool to say
ConfigureNamesEnum with say on, off and timing?). I think that's a good idea.

I just did a quick check and changing a GUC from ConfigureNamesBool to 
ConfigureNamesEnum is something that has already been done in the past (see
240067b3b0f and ffd37740ee6 for example).

In my previous up-thead message, I did not mean to suggest to add a new GUC,
just saying that when new "timing" is measured then users have the choice to
enable or disable it.

> Yes, thank you. v5 attached in [1] changes the wording as you recommend..

Thanks for the updated version!

> have any code yet that loops through all of them or anything like

Yeah makes sense.

> stilted, but I'm not sure how to fix it.

Yeah, that might be easier to reason about if we're going with Fujii-san
suggestion to extend log_connections with a new option?

> because it seems generally useful.

Great idea! Could probably be used in other places but I did not check and
it's outside the scope of this thread anyway.

> It does not however cut down on LOC, so I'm somewhat on the fence.

I think that's somehow also around code maintenance (not only LOC), say for example
if we want to add more "child_type" in the check (no need to remember to update both
locations).

Regards,

---

From: Melanie Plageman <[email-masked]>
Date: Thu, 27 Feb 2025 11:08:04 -0500

> just saying that when new "timing" is measured then users have the choice to

I was just talking to Andres off-list and he mentioned that the volume
of log_connections messages added in recent releases can really be a
problem for users. He said ideally we would emit one message which
consolidated these (and make sure we did so for failed connections too
detailing the successfully completed stages).

However, since that is a bigger project (with more refactoring, etc),
he suggested that we change log_connections to a GUC_LIST
(ConfigureNamesString) with options like "none", "received,
"authenticated", "authorized", "all".

Then we could add one like "established" for the final message and
timings my patch set adds. I think the overhead of an additional log
message being emitted probably outweighs the overhead of taking those
additional timings.

String GUCs are a lot more work than enum GUCs, so I was thinking if
there is a way to do it as an enum.

I think we want the user to be able to specify a list of all the log
messages they want included, not just have each one include the
previous ones. So, then it probably has to be a list right? There is
no good design that would fit as an enum.

> if we want to add more "child_type" in the check (no need to remember to update both

I didn't include checking the child_type in that function since it is
unrelated to instr_time, so it sadly wouldn't help with that. We could
macro-ize the child_type check were we to add another child_type.

- Melanie

---

From: Andres Freund <[email-masked]>
Date: Thu, 27 Feb 2025 11:14:56 -0500

Hi,

> ConfigureNamesEnum with say on, off and timing?). I think that's a good idea.

I don't think the timing overhead is a relevant factor here - compared to the
fork of a new connection or performing authentication the cost of taking a few
timestamps is neglegible. A timestamp costs 10s to 100s of cycles, a fork many
many millions. Even if you have a really slow timestamp function, it's still
going to be way way cheaper.

Greetings,

Andres Freund

---

From: Andres Freund <[email-masked]>
Date: Thu, 27 Feb 2025 11:30:09 -0500

Hi,

On 2025-02-27 11:08:04 -0500, Melanie Plageman wrote:
> problem for users.

For some added color: I've seen plenty systems where almost all the log volume
is log_connection messages, which they *have* to enable for various regulatory
reasons.  It'd still be a lot if we just emitted one message for each
connection, but logging three (and possibly four with $thread), for each
connection makes it substantially worse.

> He said ideally we would emit one message which consolidated these (and make
> sure we did so for failed connections too detailing the successfully
> completed stages).

A combined message would also not *quite* replace all use-cases, e.g. if you
want to debug arriving connections or auth problems you do want the additional
messages.  But yea, for normal operation, I do think most folks want just one
message.

> "authenticated", "authorized", "all".

Yep.

> message being emitted probably outweighs the overhead of taking those

To bikeshed a bit: "established" could be the TCP connection establishment
just as well. I'd go for "completed" or "timings".

> no good design that would fit as an enum.

I don't see a way to comfortably shove this into an enum either.

Greetings,

Andres Freund

---

From: Melanie Plageman <[email-masked]>
Date: Thu, 27 Feb 2025 17:55:19 -0500

> > "authenticated", "authorized", "all".

I've done a draft of this in attached v7 (see 0001). It still needs
polishing (e.g. I need to figure out where to put the new guc hook
functions and enums and such), but I want to see if this is a viable
direction forward.

I'm worried the list of possible connection log messages could get
unwieldy if we add many more.

- Melanie
From 6f7f1a2e3ea660596bee0348691e192b8c2fce24 Mon Sep 17 00:00:00 2001
From: Melanie Plageman <[email-masked]>
Date: Thu, 27 Feb 2025 17:33:38 -0500
Subject: [PATCH v7 2/2] Add connection establishment duration logging

Reviewed-by: Bertrand Drouvot <[email-masked]>
Reviewed-by: Fujii Masao <[email-masked]>
Reviewed-by: Jelte Fennema-Nio <[email-masked]>
Reviewed-by: Jacob Champion <[email-masked]>
Reviewed-by: Guillaume Lelarge <[email-masked]>
Discussion: https://postgr.es/m/flat/CAAKRu_b_smAHK0ZjrnL5GRxnAVWujEXQWpLXYzGbmpcZd3nLYw%40mail.gmail.com
---
 doc/src/sgml/config.sgml                |  2 +-
 src/backend/postmaster/launch_backend.c | 23 +++++++++++++++++++++++
 src/backend/postmaster/postmaster.c     | 12 +++++++++++-
 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     |  8 ++++++++
 src/include/tcop/backend_startup.h      |  5 +++++
 src/tools/pgindent/typedefs.list        |  1 +
 12 files changed, 97 insertions(+), 2 deletions(-)

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index c927efd22d1..82b06179a38 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -7324,7 +7324,7 @@ local0.*    /var/log/postgresql
        <para>
         Causes each attempted connection to the server to be logged, as well as
         successful completion of both client authentication (if necessary) and
-        authorization.
+        authorization. Also logs connection establishment component durations.
        </para>
 
        <para>
index 47375e5bfaa..3fe68601899 100644

+	if ((log_connections & LOG_CONNECTION_TIMINGS) &&
+		if ((log_connections & LOG_CONNECTION_TIMINGS) &&

+	if ((log_connections & LOG_CONNECTION_READY) &&
 
diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c
index aef63793aa7..71aa47c8d36 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -1536,7 +1536,7 @@ check_log_connections(char **newval, void **extra, GucSource source)
 	if (pg_strcasecmp(*newval, "none") == 0)
 		effval = "";
 	else if (pg_strcasecmp(*newval, "all") == 0)
-		effval = "received, authenticated, authorized";
+		effval = "received, authenticated, authorized, timings";
 
 	/* Need a modifiable copy of string */
 	rawstring = pstrdup(effval);
@@ -1558,6 +1558,8 @@ check_log_connections(char **newval, void **extra, GucSource source)
 			flags |= LOG_CONNECTION_AUTHENTICATED;
 		else if (pg_strcasecmp(item, "authorized") == 0)
 			flags |= LOG_CONNECTION_AUTHORIZED;
+		else if (pg_strcasecmp(item, "timings") == 0)
+			flags |= LOG_CONNECTION_TIMINGS;
 		else if (pg_strcasecmp(item, "none") == 0 || pg_strcasecmp(item, "all") == 0)
 		{
 			GUC_check_errdetail("Cannot specify \"%s\" in a list of other log_connections options.", item);
@@ -1759,7 +1761,14 @@ ServerLoop(void)
 				ClientSocket s;

 				/* We no longer need the open socket in this process */
 				if (s.sock != PGINVALID_SOCKET)
@@ -3585,6 +3594,7 @@ BackendStartup(ClientSocket *client_sock)

index f2f75aa0f88..d753c6bbd5b 100644
 
 	Assert(dbname != NULL);
 
+			/*
+				(log_connections & LOG_CONNECTION_TIMINGS) &&
 
index 8811f2ba3e6..44e086ceca7 100644
 
+	if ((log_connections & LOG_CONNECTION_TIMINGS) &&
 
+	if ((log_connections & LOG_CONNECTION_TIMINGS) &&
 	if (log_connections & LOG_CONNECTION_AUTHORIZED)

 /*
 
 #ifdef USE_SSL

 
index adc693a6b2b..dae7551e7ad 100644
 
 #include "lib/ilist.h"
 #include "miscadmin.h"
 
 /*
  * A struct representing an active postmaster child process.  This is used
@@ -127,6 +128,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
@@ -149,6 +156,7 @@ typedef enum ConnectionLogType
 	LOG_CONNECTION_RECEIVED,
 	LOG_CONNECTION_AUTHENTICATED,
 	LOG_CONNECTION_AUTHORIZED,
+	LOG_CONNECTION_TIMINGS,
 } ConnectionLogType;
 
 #endif							/* _POSTMASTER_H */

 
 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 59839013d28..ea7163fdada 100644
--- a/src/tools/pgindent/typedefs.list
+++ b/src/tools/pgindent/typedefs.list
@@ -485,6 +485,7 @@ ConnStatusType
 ConnType
 ConnectionLogType
 ConnectionStateEnum
+ConnectionTiming
 ConsiderSplitContext
 Const
 ConstrCheck
-- 
2.34.1

From 6178535e0be8e25e4209f42d52c8402b6d1e4724 Mon Sep 17 00:00:00 2001
From: Melanie Plageman <[email-masked]>
Date: Thu, 27 Feb 2025 17:32:17 -0500
Subject: [PATCH v7 1/2] Make log_connections a list

Instead of a boolean, make log_connections a list of the possible log
connections events to log. all and none mimic current behavior of on and
off. This is in response to feedback that log_connections logs too many
messages.
---
 doc/src/sgml/config.sgml                      | 25 ++++--
 src/backend/libpq/auth.c                      |  5 +-
 src/backend/postmaster/postmaster.c           | 76 ++++++++++++++++++-
 src/backend/tcop/backend_startup.c            |  2 +-
 src/backend/utils/init/postinit.c             |  2 +-
 src/backend/utils/misc/guc_tables.c           | 20 ++---
 src/backend/utils/misc/postgresql.conf.sample |  4 +-
 src/include/postmaster/postmaster.h           | 10 ++-
 src/include/utils/guc_hooks.h                 |  2 +
 .../libpq/t/005_negotiate_encryption.pl       |  2 +-
 src/test/authentication/t/001_password.pl     |  2 +-
 src/test/authentication/t/003_peer.pl         |  2 +-
 src/test/authentication/t/005_sspi.pl         |  2 +-
 src/test/kerberos/t/001_auth.pl               |  2 +-
 src/test/ldap/t/001_auth.pl                   |  2 +-
 src/test/ldap/t/002_bindpasswd.pl             |  2 +-
 .../t/001_mutated_bindpasswd.pl               |  2 +-
 .../modules/oauth_validator/t/001_server.pl   |  2 +-
 .../modules/oauth_validator/t/002_client.pl   |  2 +-
 .../postmaster/t/002_connection_limits.pl     |  2 +-
 src/test/postmaster/t/003_start_stop.pl       |  2 +-
 src/test/recovery/t/013_crash_restart.pl      |  2 +-
 src/test/recovery/t/022_crash_temp_files.pl   |  2 +-
 src/test/recovery/t/032_relfilenode_reuse.pl  |  2 +-
 src/test/recovery/t/037_invalid_database.pl   |  2 +-
 src/test/ssl/t/SSL/Server.pm                  |  2 +-
 src/tools/ci/pg_ci_base.conf                  |  2 +-
 src/tools/pgindent/typedefs.list              |  1 +
 28 files changed, 141 insertions(+), 42 deletions(-)

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index e55700f35b8..c927efd22d1 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -140,7 +140,7 @@
      An example of what this file might look like is:
 <programlisting>
 # This is a comment
-log_connections = yes
+log_connections = 'all'
 log_destination = 'syslog'
 search_path = '"$user", public'
 shared_buffers = 128MB
@@ -337,7 +337,7 @@ UPDATE pg_settings SET setting = reset_val WHERE name = 'configuration_parameter
        <option>-c name=value</option> command-line parameter, or its equivalent
        <option>--name=value</option> variation.  For example,
 <programlisting>
-postgres -c log_connections=yes --log-destination='syslog'
+postgres -c log_connections='all' --log-destination='syslog'
 </programlisting>
        Settings provided in this way override those set via
        <filename>postgresql.conf</filename> or <command>ALTER SYSTEM</command>,
@@ -7315,20 +7315,31 @@ 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>string</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.
+       </para>
+
+       <para>
+        May be set to <literal>none</literal> to disable this logging,
+        <literal>all</literal> to enable all connection log message types, or a
+        comma-separated list of the specific connection log message types to
+        emit. The valid options are <literal>received</literal>,
+        <literal>authenticated</literal>, and <literal>authorized</literal>.
+       </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>.
+        The default is <literal>'none'</literal>.
        </para>
 
        <note>
diff --git a/src/backend/libpq/auth.c b/src/backend/libpq/auth.c
index 81e2f8184e3..b4cc8cb4dd1 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_AUTHENTICATED)
 	{
 		ereport(LOG,
 				errmsg("connection authenticated: identity=\"%s\" method=%s "
@@ -633,7 +633,8 @@ ClientAuthentication(Port *port)
 #endif
 	}
 
-	if (Log_connections && status == STATUS_OK &&
+	if ((log_connections & LOG_CONNECTION_AUTHENTICATED) &&
+		status == STATUS_OK &&
 		!MyClientConnectionInfo.authn_id)
 	{
 		/*
diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c
index 5dd3b6a4fd4..aef63793aa7 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -118,6 +118,7 @@
 #include "utils/pidfile.h"
 #include "utils/timestamp.h"
 #include "utils/varlena.h"
+#include "utils/guc_hooks.h"
 
 #ifdef EXEC_BACKEND
 #include "common/file_utils.h"
@@ -237,7 +238,8 @@ int			PreAuthDelay = 0;
 int			AuthenticationTimeout = 60;
 
 bool		log_hostname;		/* for ps display and logging */
-bool		Log_connections = false;
+char	   *log_connections_string = NULL;
+int			log_connections = 0;
 
 bool		enable_bonjour = false;
 char	   *bonjour_name;
@@ -1517,6 +1519,78 @@ checkControlFile(void)
 	FreeFile(fp);
 }
 
+bool
+check_log_connections(char **newval, void **extra, GucSource source)
+{
+	int			flags = 0;
+	char	   *rawstring = NULL;
+	List	   *elemlist;
+	ListCell   *l;
+
+	char	   *effval = *newval;
+
+	/*
+	 * log_connections can be "all" or "none" or a list of comma separated
+	 * options
+	 */
+	if (pg_strcasecmp(*newval, "none") == 0)
+		effval = "";
+	else if (pg_strcasecmp(*newval, "all") == 0)
+		effval = "received, authenticated, authorized";
+
+	/* Need a modifiable copy of string */
+	rawstring = pstrdup(effval);
+
+	if (!SplitGUCList(rawstring, ',', &elemlist))
+	{
+		GUC_check_errdetail("Invalid list syntax in parameter \"%s\".",
+							"log_connections");
+		goto error;
+	}
+
+	foreach(l, elemlist)
+	{
+		char	   *item = (char *) lfirst(l);
+
+		if (pg_strcasecmp(item, "received") == 0)
+			flags |= LOG_CONNECTION_RECEIVED;
+		else if (pg_strcasecmp(item, "authenticated") == 0)
+			flags |= LOG_CONNECTION_AUTHENTICATED;
+		else if (pg_strcasecmp(item, "authorized") == 0)
+			flags |= LOG_CONNECTION_AUTHORIZED;
+		else if (pg_strcasecmp(item, "none") == 0 || pg_strcasecmp(item, "all") == 0)
+		{
+			GUC_check_errdetail("Cannot specify \"%s\" in a list of other log_connections options.", item);
+			goto error;
+		}
+		else
+		{
+			GUC_check_errdetail("Invalid option \"%s\".", item);
+			goto error;
+		}
+	}
+
+	pfree(rawstring);
+	list_free(elemlist);
+
+	/* Save the flags in *extra, for use by assign_log_connections */
+	*extra = guc_malloc(ERROR, sizeof(int));
+	*((int *) *extra) = flags;
+
+	return true;
+
+error:
+	pfree(rawstring);
+	list_free(elemlist);
+	return false;
+}
+
+void
+assign_log_connections(const char *newval, void *extra)
+{
+	log_connections = *((int *) extra);
+}
+
 /*
  * Determine how long should we let ServerLoop sleep, in milliseconds.
  *
diff --git a/src/backend/tcop/backend_startup.c b/src/backend/tcop/backend_startup.c
index c70746fa562..2c208c25356 100644
--- a/src/backend/tcop/backend_startup.c
+++ b/src/backend/tcop/backend_startup.c
@@ -202,7 +202,7 @@ BackendInitialize(ClientSocket *client_sock, CAC_state cac)
 	port->remote_port = MemoryContextStrdup(TopMemoryContext, remote_port);
 
 	/* And now we can issue the Log_connections message, if wanted */
-	if (Log_connections)
+	if (log_connections & LOG_CONNECTION_RECEIVED)
 	{
 		if (remote_port[0])
 			ereport(LOG,
diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
index 318600d6d02..8811f2ba3e6 100644
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -251,7 +251,7 @@ PerformAuthentication(Port *port)
 	 */
 	disable_timeout(STATEMENT_TIMEOUT, false);
 
-	if (Log_connections)
+	if (log_connections & LOG_CONNECTION_AUTHORIZED)
 	{
 		StringInfoData logmsg;
 
diff --git a/src/backend/utils/misc/guc_tables.c b/src/backend/utils/misc/guc_tables.c
index ad25cbb39c5..7dfa11810a8 100644
--- a/src/backend/utils/misc/guc_tables.c
+++ b/src/backend/utils/misc/guc_tables.c
@@ -1219,15 +1219,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."),
@@ -4850,6 +4841,17 @@ struct config_string ConfigureNamesString[] =
 		check_debug_io_direct, assign_debug_io_direct, NULL
 	},
 
+	{
+		{"log_connections", PGC_SU_BACKEND, LOGGING_WHAT,
+			gettext_noop("Logs information about successful connection."),
+			NULL,
+			GUC_LIST_INPUT
+		},
+		&log_connections_string,
+		"none",
+		check_log_connections, assign_log_connections, NULL
+	},
+
 	{
 		{"synchronized_standby_slots", PGC_SIGHUP, REPLICATION_PRIMARY,
 			gettext_noop("Lists streaming replication standby server replication slot "
diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index 5362ff80519..4f54719dd9e 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -21,7 +21,7 @@
 # require a server shutdown and restart to take effect.
 #
 # Any parameter can also be given as a command-line option to the server, e.g.,
-# "postgres -c log_connections=on".  Some parameters can be changed at run time
+# "postgres -c log_connections='all'".  Some parameters can be changed at run time
 # with the "SET" SQL command.
 #
 # Memory units:  B  = bytes            Time units:  us  = microseconds
@@ -578,7 +578,7 @@
 					# actions running at least this number
 					# of milliseconds.
 #log_checkpoints = on
-#log_connections = off
+#log_connections = 'none'
 #log_disconnections = off
 #log_duration = off
 #log_error_verbosity = default		# terse, default, or verbose messages
diff --git a/src/include/postmaster/postmaster.h b/src/include/postmaster/postmaster.h
index b6a3f275a1b..adc693a6b2b 100644
--- a/src/include/postmaster/postmaster.h
+++ b/src/include/postmaster/postmaster.h
@@ -63,7 +63,8 @@ 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 char *log_connections_string;
 extern PGDLLIMPORT bool log_hostname;
 extern PGDLLIMPORT bool enable_bonjour;
 extern PGDLLIMPORT char *bonjour_name;
@@ -143,4 +144,11 @@ typedef enum DispatchOption
 
 extern DispatchOption parse_dispatch_option(const char *name);
 
+typedef enum ConnectionLogType
+{
+	LOG_CONNECTION_RECEIVED,
+	LOG_CONNECTION_AUTHENTICATED,
+	LOG_CONNECTION_AUTHORIZED,
+} ConnectionLogType;
+
 #endif							/* _POSTMASTER_H */
diff --git a/src/include/utils/guc_hooks.h b/src/include/utils/guc_hooks.h
index 951451a9765..9a0d8ec85c7 100644
--- a/src/include/utils/guc_hooks.h
+++ b/src/include/utils/guc_hooks.h
@@ -51,6 +51,8 @@ extern bool check_datestyle(char **newval, void **extra, GucSource source);
 extern void assign_datestyle(const char *newval, void *extra);
 extern bool check_debug_io_direct(char **newval, void **extra, GucSource source);
 extern void assign_debug_io_direct(const char *newval, void *extra);
+extern bool check_log_connections(char **newval, void **extra, GucSource source);
+extern void assign_log_connections(const char *newval, void *extra);
 extern bool check_default_table_access_method(char **newval, void **extra,
 											  GucSource source);
 extern bool check_default_tablespace(char **newval, void **extra,
diff --git a/src/interfaces/libpq/t/005_negotiate_encryption.pl b/src/interfaces/libpq/t/005_negotiate_encryption.pl
index c834fa5149a..cb56e09d50b 100644
--- a/src/interfaces/libpq/t/005_negotiate_encryption.pl
+++ b/src/interfaces/libpq/t/005_negotiate_encryption.pl
@@ -107,7 +107,7 @@ $node->append_conf(
 listen_addresses = '$hostaddr'
 
 # Capturing the EVENTS that occur during tests requires these settings
-log_connections = on
+log_connections = 'all'
 log_disconnections = on
 trace_connection_negotiation = on
 lc_messages = 'C'
diff --git a/src/test/authentication/t/001_password.pl b/src/test/authentication/t/001_password.pl
index 4ce22ccbdf2..72c187fbdc0 100644
--- a/src/test/authentication/t/001_password.pl
+++ b/src/test/authentication/t/001_password.pl
@@ -63,7 +63,7 @@ sub test_conn
 # Initialize primary node
 my $node = PostgreSQL::Test::Cluster->new('primary');
 $node->init;
-$node->append_conf('postgresql.conf', "log_connections = on\n");
+$node->append_conf('postgresql.conf', "log_connections = 'all'\n");
 $node->start;
 
 # could fail in FIPS mode
diff --git a/src/test/authentication/t/003_peer.pl b/src/test/authentication/t/003_peer.pl
index 69ba73bd2b9..8e1b0477d6b 100644
--- a/src/test/authentication/t/003_peer.pl
+++ b/src/test/authentication/t/003_peer.pl
@@ -71,7 +71,7 @@ sub test_role
 
 my $node = PostgreSQL::Test::Cluster->new('node');
 $node->init;
-$node->append_conf('postgresql.conf', "log_connections = on\n");
+$node->append_conf('postgresql.conf', "log_connections = 'all'\n");
 $node->start;
 
 # Set pg_hba.conf with the peer authentication.
diff --git a/src/test/authentication/t/005_sspi.pl b/src/test/authentication/t/005_sspi.pl
index b480b702590..f9b61babcd7 100644
--- a/src/test/authentication/t/005_sspi.pl
+++ b/src/test/authentication/t/005_sspi.pl
@@ -18,7 +18,7 @@ if (!$windows_os || $use_unix_sockets)
 # Initialize primary node
 my $node = PostgreSQL::Test::Cluster->new('primary');
 $node->init;
-$node->append_conf('postgresql.conf', "log_connections = on\n");
+$node->append_conf('postgresql.conf', "log_connections = 'all'\n");
 $node->start;
 
 my $huge_pages_status =
diff --git a/src/test/kerberos/t/001_auth.pl b/src/test/kerberos/t/001_auth.pl
index 6748b109dec..afc3130e720 100644
--- a/src/test/kerberos/t/001_auth.pl
+++ b/src/test/kerberos/t/001_auth.pl
@@ -65,7 +65,7 @@ $node->append_conf(
 	'postgresql.conf', qq{
 listen_addresses = '$hostaddr'
 krb_server_keyfile = '$krb->{keytab}'
-log_connections = on
+log_connections = 'all'
 lc_messages = 'C'
 });
 $node->start;
diff --git a/src/test/ldap/t/001_auth.pl b/src/test/ldap/t/001_auth.pl
index 352b0fc1fa7..b6ee386679d 100644
--- a/src/test/ldap/t/001_auth.pl
+++ b/src/test/ldap/t/001_auth.pl
@@ -47,7 +47,7 @@ note "setting up PostgreSQL instance";
 
 my $node = PostgreSQL::Test::Cluster->new('node');
 $node->init;
-$node->append_conf('postgresql.conf', "log_connections = on\n");
+$node->append_conf('postgresql.conf', "log_connections = 'all'\n");
 $node->start;
 
 $node->safe_psql('postgres', 'CREATE USER test0;');
diff --git a/src/test/ldap/t/002_bindpasswd.pl b/src/test/ldap/t/002_bindpasswd.pl
index f8beba2b279..2acf96aeb6d 100644
--- a/src/test/ldap/t/002_bindpasswd.pl
+++ b/src/test/ldap/t/002_bindpasswd.pl
@@ -43,7 +43,7 @@ note "setting up PostgreSQL instance";
 
 my $node = PostgreSQL::Test::Cluster->new('node');
 $node->init;
-$node->append_conf('postgresql.conf', "log_connections = on\n");
+$node->append_conf('postgresql.conf', "log_connections = 'all'\n");
 $node->start;
 
 $node->safe_psql('postgres', 'CREATE USER test0;');
diff --git a/src/test/modules/ldap_password_func/t/001_mutated_bindpasswd.pl b/src/test/modules/ldap_password_func/t/001_mutated_bindpasswd.pl
index 9b062e1c800..4591b5568a8 100644
--- a/src/test/modules/ldap_password_func/t/001_mutated_bindpasswd.pl
+++ b/src/test/modules/ldap_password_func/t/001_mutated_bindpasswd.pl
@@ -42,7 +42,7 @@ note "setting up PostgreSQL instance";
 
 my $node = PostgreSQL::Test::Cluster->new('node');
 $node->init;
-$node->append_conf('postgresql.conf', "log_connections = on\n");
+$node->append_conf('postgresql.conf', "log_connections = 'all'\n");
 $node->append_conf('postgresql.conf',
 	"shared_preload_libraries = 'ldap_password_func'");
 $node->start;
diff --git a/src/test/modules/oauth_validator/t/001_server.pl b/src/test/modules/oauth_validator/t/001_server.pl
index 6fa59fbeb25..27829680439 100644
--- a/src/test/modules/oauth_validator/t/001_server.pl
+++ b/src/test/modules/oauth_validator/t/001_server.pl
@@ -43,7 +43,7 @@ if ($ENV{with_python} ne 'yes')
 
 my $node = PostgreSQL::Test::Cluster->new('primary');
 $node->init;
-$node->append_conf('postgresql.conf', "log_connections = on\n");
+$node->append_conf('postgresql.conf', "log_connections = 'all'\n");
 $node->append_conf('postgresql.conf',
 	"oauth_validator_libraries = 'validator'\n");
 $node->start;
diff --git a/src/test/modules/oauth_validator/t/002_client.pl b/src/test/modules/oauth_validator/t/002_client.pl
index ab83258d736..aa944ba5f2f 100644
--- a/src/test/modules/oauth_validator/t/002_client.pl
+++ b/src/test/modules/oauth_validator/t/002_client.pl
@@ -26,7 +26,7 @@ if (!$ENV{PG_TEST_EXTRA} || $ENV{PG_TEST_EXTRA} !~ /\boauth\b/)
 
 my $node = PostgreSQL::Test::Cluster->new('primary');
 $node->init;
-$node->append_conf('postgresql.conf', "log_connections = on\n");
+$node->append_conf('postgresql.conf', "log_connections = 'all'\n");
 $node->append_conf('postgresql.conf',
 	"oauth_validator_libraries = 'validator'\n");
 $node->start;
diff --git a/src/test/postmaster/t/002_connection_limits.pl b/src/test/postmaster/t/002_connection_limits.pl
index 8cfa6e0ced5..a221501c206 100644
--- a/src/test/postmaster/t/002_connection_limits.pl
+++ b/src/test/postmaster/t/002_connection_limits.pl
@@ -19,7 +19,7 @@ $node->init(
 $node->append_conf('postgresql.conf', "max_connections = 6");
 $node->append_conf('postgresql.conf', "reserved_connections = 2");
 $node->append_conf('postgresql.conf', "superuser_reserved_connections = 1");
-$node->append_conf('postgresql.conf', "log_connections = on");
+$node->append_conf('postgresql.conf', "log_connections = 'all'");
 $node->start;
 
 $node->safe_psql(
diff --git a/src/test/postmaster/t/003_start_stop.pl b/src/test/postmaster/t/003_start_stop.pl
index 036b296f72b..08cd7a4857e 100644
--- a/src/test/postmaster/t/003_start_stop.pl
+++ b/src/test/postmaster/t/003_start_stop.pl
@@ -29,7 +29,7 @@ $node->append_conf('postgresql.conf', "max_connections = 5");
 $node->append_conf('postgresql.conf', "max_wal_senders = 0");
 $node->append_conf('postgresql.conf', "autovacuum_max_workers = 1");
 $node->append_conf('postgresql.conf', "max_worker_processes = 1");
-$node->append_conf('postgresql.conf', "log_connections = on");
+$node->append_conf('postgresql.conf', "log_connections = 'all'");
 $node->append_conf('postgresql.conf', "log_min_messages = debug2");
 $node->append_conf('postgresql.conf',
 	"authentication_timeout = '$authentication_timeout s'");
diff --git a/src/test/recovery/t/013_crash_restart.pl b/src/test/recovery/t/013_crash_restart.pl
index cd848918d00..2b6ec94cd75 100644
--- a/src/test/recovery/t/013_crash_restart.pl
+++ b/src/test/recovery/t/013_crash_restart.pl
@@ -27,7 +27,7 @@ $node->start();
 $node->safe_psql(
 	'postgres',
 	q[ALTER SYSTEM SET restart_after_crash = 1;
-				   ALTER SYSTEM SET log_connections = 1;
+				   ALTER SYSTEM SET log_connections = 'all';
 				   SELECT pg_reload_conf();]);
 
 # Run psql, keeping session alive, so we have an alive backend to kill.
diff --git a/src/test/recovery/t/022_crash_temp_files.pl b/src/test/recovery/t/022_crash_temp_files.pl
index 483a416723f..5d4b695c193 100644
--- a/src/test/recovery/t/022_crash_temp_files.pl
+++ b/src/test/recovery/t/022_crash_temp_files.pl
@@ -26,7 +26,7 @@ $node->start();
 $node->safe_psql(
 	'postgres',
 	q[ALTER SYSTEM SET remove_temp_files_after_crash = on;
-				   ALTER SYSTEM SET log_connections = 1;
+				   ALTER SYSTEM SET log_connections = 'all';
 				   ALTER SYSTEM SET work_mem = '64kB';
 				   ALTER SYSTEM SET restart_after_crash = on;
 				   SELECT pg_reload_conf();]);
diff --git a/src/test/recovery/t/032_relfilenode_reuse.pl b/src/test/recovery/t/032_relfilenode_reuse.pl
index ddb7223b337..388a50add7a 100644
--- a/src/test/recovery/t/032_relfilenode_reuse.pl
+++ b/src/test/recovery/t/032_relfilenode_reuse.pl
@@ -14,7 +14,7 @@ $node_primary->init(allows_streaming => 1);
 $node_primary->append_conf(
 	'postgresql.conf', q[
 allow_in_place_tablespaces = true
-log_connections=on
+log_connections='all'
 # to avoid "repairing" corruption
 full_page_writes=off
 log_min_messages=debug2
diff --git a/src/test/recovery/t/037_invalid_database.pl b/src/test/recovery/t/037_invalid_database.pl
index bdf39397397..ea62650b767 100644
--- a/src/test/recovery/t/037_invalid_database.pl
+++ b/src/test/recovery/t/037_invalid_database.pl
@@ -15,7 +15,7 @@ $node->append_conf(
 autovacuum = off
 max_prepared_transactions=5
 log_min_duration_statement=0
-log_connections=on
+log_connections='all'
 log_disconnections=on
 ));
 
diff --git a/src/test/ssl/t/SSL/Server.pm b/src/test/ssl/t/SSL/Server.pm
index 447469d8937..7bc45ee7611 100644
--- a/src/test/ssl/t/SSL/Server.pm
+++ b/src/test/ssl/t/SSL/Server.pm
@@ -200,7 +200,7 @@ sub configure_test_server_for_ssl
 	$node->append_conf(
 		'postgresql.conf', <<EOF
 fsync=off
-log_connections=on
+log_connections='all'
 log_hostname=on
 listen_addresses='$serverhost'
 log_statement=all
diff --git a/src/tools/ci/pg_ci_base.conf b/src/tools/ci/pg_ci_base.conf
index d8faa9c26c1..5593827eb4f 100644
--- a/src/tools/ci/pg_ci_base.conf
+++ b/src/tools/ci/pg_ci_base.conf
@@ -8,7 +8,7 @@ max_prepared_transactions = 10
 # Settings that make logs more useful
 log_autovacuum_min_duration = 0
 log_checkpoints = true
-log_connections = true
+log_connections = 'all'
 log_disconnections = true
 log_line_prefix = '%m [%p][%b] %q[%a][%v:%x] '
 log_lock_waits = true
diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list
index cfbab589d61..59839013d28 100644
--- a/src/tools/pgindent/typedefs.list
+++ b/src/tools/pgindent/typedefs.list
@@ -483,6 +483,7 @@ ConnCacheKey
 ConnParams
 ConnStatusType
 ConnType
+ConnectionLogType
 ConnectionStateEnum
 ConsiderSplitContext
 Const
-- 
2.34.1

---

From: Bertrand Drouvot <[email-masked]>
Date: Fri, 28 Feb 2025 05:14:17 +0000

Hi,

> going to be way way cheaper.

That's a very good point, it has to be put in perspective. The difference in
scale is so significant that the timing collection shouldn't be a concern.
Fair point!

Now I'm thinking what about "if" the connection was on a multi-threaded model?

I think we could reach the same conclusion as thread creation overhead is 
still substantial (allocating stack space, initializing thread state, and other
kernel-level operations) as compare to a really slow timestamp function.

Regards,

---

From: Bertrand Drouvot <[email-masked]>
Date: Fri, 28 Feb 2025 05:16:21 +0000

Hi,

> no good design that would fit as an enum.

Interesting idea... Yeah, that would sound weird with an enum. I could think
about providing an enum per possible combination but I think that would
generate things like 2^N enum and won't be really user friendly (also that would
double each time we'd want to add a new possible "value" becoming quickly
unmanageable).

So yeah, I can't think of anything better than GUC_LIST.

> macro-ize the child_type check were we to add another child_type.

Yup but my idea was to put all those line:

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

into a dedicated helper function.

Regards,

---

From: Bertrand Drouvot <[email-masked]>
Date: Fri, 28 Feb 2025 05:54:44 +0000

Hi,

On Thu, Feb 27, 2025 at 05:55:19PM -0500, Melanie Plageman wrote:
> I've done a draft of this in attached v7 (see 0001).

Thanks for the patch!

> It still needs polishing (e.g. I need to figure out where to put the new guc hook
> functions and enums and such)

yeah, I wonder if it would make sense to create new dedicated "connection_logging"
file(s).

>, but I want to see if this is a viable direction forward.
> 

Thinking out loud, I'm not sure we'd add "many more" but maybe what we could do
is to introduce some predefined groups like:

'basic' (that would be equivalent to 'received, + timings introduced in 0002')
'security' (equivalent to 'authenticated,authorized')

Not saying we need to create this kind of predefined groups now, just an idea
in case we'd add many more: that could "help" the user experience, or are you
more concerned about the code maintenance?

Just did a quick test, (did not look closely at the code), and it looks like
that:

'all': does not report the "received" (but does report authenticated and authorized)
'received': does not work?
'authenticated': works
'authorized': works

Regards,

---

From: Melanie Plageman <[email-masked]>
Date: Fri, 28 Feb 2025 17:42:37 -0500

> into a dedicated helper function.

I ended up finding a bug that means that that exact code isn't
duplicated twice now. For EXEC_BACKEND, I have to wait to calculate
the duration until after reading the GUC values but I need to get the
fork end time before that.

I tried coming up with an inline helper to replace this and most
things I tried felt awkward. It has to have backend type and start
time as parameters. And all of these places we have to be super
careful that the GUCs have already been read before using
log_connections, so it seems a bit unsafe to check log_connections
(the global variable) in a function. Someone could call the function
in a different place and maybe not know that log_connections won't be
set there.

Also, I also wasn't sure if it would be weird to call a function like
"LogConnectionTiming()" which in many cases doesn't log the connection
timing (because it is a different backend type).

But maybe I'm not thinking about it correctly. What were you imagining?

- Melanie

---

From: Melanie Plageman <[email-masked]>
Date: Fri, 28 Feb 2025 17:52:35 -0500

> yeah, I wonder if it would make sense to create new dedicated "connection_logging"

I think for now there isn't enough for a new file. I think these are
probably okay in postmaster.c since this has to do with postmaster
starting new connections.

> more concerned about the code maintenance?

I was more worried about the user having to provide very long lists.
But groupings could be a sensible solution in the future.

> 'received': does not work?

Thanks for testing! Ouch, there were many bugs in that prototype. My
enums were broken and a few other things.

I found some bugs in 0002 as well.  Attached v8 fixes the issues I found so far.

We have to be really careful about when log_connections is actually
set before we use it -- I fixed some issues with that.

I decided to move the creation_time out of ClientSocket and into
BackendStartupData, but that meant I had to save it in the
ConnectionTiming because we don't have access to the
BackendStartupData anymore in PostgresMain(). That means
ConnectionTiming is now a mixture of times and durations. I think that
should be okay (i.e. not too confusing and gross), but I'm not sure.
It is called ConnectionTiming and not ConnectionDuration, after all.

- Melanie
From 0ee1cd306a4c27e5ec0d1860ce7cd219bb761fed Mon Sep 17 00:00:00 2001
From: Melanie Plageman <[email-masked]>
Date: Thu, 27 Feb 2025 17:32:17 -0500
Subject: [PATCH v8 1/2] Modularize log_connections output

Convert the boolean log_connections GUC into a list GUC of the
connection stages to log. This obsoletes log_disconnections, as
'disconnected' is now a log_connections option.

The current log_connections options are 'received', 'authenticated',
'authorized', and 'disconnected'. The empty string disables all
connection logging. 'all' enables all available connection logging.

This gives users more control over the volume of connection logging.

This patch has the same behavior as [1] but was developed independently.
The idea to replace log_disconnections with a log_connections option
does, however, come from that thread.

[1] https://www.postgresql.org/message-id/flat/CAA8Fd-qCB96uwfgMKrzfNs32mqqysi53yZFNVaRNJ6xDthZEgA%40mail.gmail.com

Discussion: https://postgr.es/m/flat/Z8FPpJPDLHWNuV2c%40ip-10-97-1-34.eu-west-3.compute.internal#35525b4425c5f8ecfe52ec6ad859ef9a
---
 doc/src/sgml/config.sgml                      | 48 +++++-------
 src/backend/libpq/auth.c                      |  8 +-
 src/backend/postmaster/postmaster.c           | 77 ++++++++++++++++++-
 src/backend/tcop/backend_startup.c            |  4 +-
 src/backend/tcop/postgres.c                   | 13 +---
 src/backend/utils/init/postinit.c             |  2 +-
 src/backend/utils/misc/guc_tables.c           | 29 +++----
 src/backend/utils/misc/postgresql.conf.sample |  5 +-
 src/include/postmaster/postmaster.h           | 16 +++-
 src/include/tcop/tcopprot.h                   |  1 -
 src/include/utils/guc_hooks.h                 |  2 +
 .../libpq/t/005_negotiate_encryption.pl       |  3 +-
 src/test/authentication/t/001_password.pl     |  2 +-
 src/test/authentication/t/003_peer.pl         |  2 +-
 src/test/authentication/t/005_sspi.pl         |  2 +-
 src/test/kerberos/t/001_auth.pl               |  2 +-
 src/test/ldap/t/001_auth.pl                   |  2 +-
 src/test/ldap/t/002_bindpasswd.pl             |  2 +-
 .../t/001_mutated_bindpasswd.pl               |  2 +-
 .../modules/oauth_validator/t/001_server.pl   |  2 +-
 .../modules/oauth_validator/t/002_client.pl   |  2 +-
 .../postmaster/t/002_connection_limits.pl     |  2 +-
 src/test/postmaster/t/003_start_stop.pl       |  2 +-
 src/test/recovery/t/013_crash_restart.pl      |  2 +-
 src/test/recovery/t/022_crash_temp_files.pl   |  2 +-
 src/test/recovery/t/032_relfilenode_reuse.pl  |  2 +-
 src/test/recovery/t/037_invalid_database.pl   |  3 +-
 src/test/ssl/t/SSL/Server.pm                  |  2 +-
 src/tools/ci/pg_ci_base.conf                  |  3 +-
 src/tools/pgindent/typedefs.list              |  1 +
 30 files changed, 155 insertions(+), 90 deletions(-)

index e55700f35b8..4d2bbb3f720 100644
@@ -7315,20 +7315,28 @@ 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>string</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.
-        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>.
+        Causes the specified stages of each connection attempt to the server to
+        be logged. 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>''</literal> which causes no connection logging messages to be
+        emitted.
+       </para>
+
+       <para>
+        May be set to <literal>''</literal> to disable connection logging,
+        <literal>'all'</literal> to log all available connection stages, or a
+        comma-separated list of specific connection stages to log. The valid
+        options are <literal>received</literal>,
+        <literal>authenticated</literal>, <literal>authorized</literal>, and
+        <literal>disconnected</literal>.
        </para>
 
        <note>
@@ -7342,26 +7350,6 @@ local0.*    /var/log/postgresql
       </listitem>
      </varlistentry>
 
-     <varlistentry id="guc-log-disconnections" xreflabel="log_disconnections">
-      <term><varname>log_disconnections</varname> (<type>boolean</type>)
-      <indexterm>
-       <primary><varname>log_disconnections</varname> configuration parameter</primary>
-      </indexterm>
-      </term>
-      <listitem>
-       <para>
-        Causes session terminations to be logged.  The log output
-        provides information similar to <varname>log_connections</varname>,
-        plus the duration of the session.
-        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>
-      </listitem>
-     </varlistentry>
-
-
      <varlistentry id="guc-log-duration" xreflabel="log_duration">
       <term><varname>log_duration</varname> (<type>boolean</type>)
       <indexterm>
diff --git a/src/backend/libpq/auth.c b/src/backend/libpq/auth.c
index 81e2f8184e3..da7b46720d4 100644
--- a/src/backend/libpq/auth.c
+++ b/src/backend/libpq/auth.c
@@ -317,7 +317,8 @@ auth_failed(Port *port, int status, const char *logdetail)
 /*
  * Sets the authenticated identity for the current user.  The provided string
  * will be stored into MyClientConnectionInfo, alongside the current HBA
- * method in use.  The ID will be logged if log_connections is enabled.
+ * method in use.  The ID will be logged if log_connections has the
+ * 'authenticated' option specified.
  *
  * Auth methods should call this routine exactly once, as soon as the user is
  * successfully authenticated, even if they have reasons to know that
@@ -349,7 +350,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_AUTHENTICATED)
 	{
 		ereport(LOG,
 				errmsg("connection authenticated: identity=\"%s\" method=%s "
@@ -633,7 +634,8 @@ ClientAuthentication(Port *port)
 #endif
 	}
 
index 5dd3b6a4fd4..315f5a55a34 100644
 
 #ifdef EXEC_BACKEND

 bool		enable_bonjour = false;
 char	   *bonjour_name;
@@ -1517,6 +1519,79 @@ checkControlFile(void)
 	FreeFile(fp);
 }
 
+/*
+ * Validate the input for the log_connections GUC.
+ */
+bool
+check_log_connections(char **newval, void **extra, GucSource source)
+{
+	int			flags = 0;
+	char	   *rawstring = NULL;
+	List	   *elemlist;
+	ListCell   *l;
+
+	char	   *effval = *newval;
+
+	/*
+	 * log_connections can be 'all', '', or a list of comma-separated options.
+	 */
+	if (pg_strcasecmp(*newval, "all") == 0)
+		effval = "received, authenticated, authorized, disconnected";
+
+	/* Need a modifiable copy of string */
+	rawstring = pstrdup(effval);
+
+	if (!SplitGUCList(rawstring, ',', &elemlist))
+	{
+		GUC_check_errdetail("Invalid list syntax in parameter \"log_connections\".");
+		goto log_connections_error;
+	}
+
+	foreach(l, elemlist)
+	{
+		char	   *item = (char *) lfirst(l);
+
+		if (pg_strcasecmp(item, "received") == 0)
+			flags |= LOG_CONNECTION_RECEIVED;
+		else if (pg_strcasecmp(item, "authenticated") == 0)
+			flags |= LOG_CONNECTION_AUTHENTICATED;
+		else if (pg_strcasecmp(item, "authorized") == 0)
+			flags |= LOG_CONNECTION_AUTHORIZED;
+		else if (pg_strcasecmp(item, "disconnected") == 0)
+			flags |= LOG_CONNECTION_DISCONNECTED;
+		else if (pg_strcasecmp(item, "all") == 0)
+		{
+			GUC_check_errdetail("Must specify \"all\" alone with no additional options, whitespace, or characters.");
+			goto log_connections_error;
+		}
+		else
+		{
+			GUC_check_errdetail("Invalid option \"%s\".", item);
+			goto log_connections_error;
+		}
+	}
+
+	pfree(rawstring);
+	list_free(elemlist);
+
+	/* Save the flags in *extra, for use by assign_log_connections */
+	*extra = guc_malloc(ERROR, sizeof(int));
+	*((int *) *extra) = flags;
+
+	return true;
+
+log_connections_error:
+	pfree(rawstring);
+	list_free(elemlist);
+	return false;
+}
+
+void
+assign_log_connections(const char *newval, void *extra)
+{
+	log_connections = *((int *) extra);
+}
+
 /*
  * Determine how long should we let ServerLoop sleep, in milliseconds.
  *
diff --git a/src/backend/tcop/backend_startup.c b/src/backend/tcop/backend_startup.c
index c70746fa562..887c2f177ef 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_RECEIVED)
 	{
 		if (remote_port[0])
 			ereport(LOG,
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index f2f75aa0f88..8b403a6cc3d 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -89,9 +89,6 @@ const char *debug_query_string; /* client-supplied query string */
 /* Note: whereToSendOutput is initialized for the bootstrap/standalone case */
 CommandDest whereToSendOutput = DestDebug;
 
-/* flag for logging end of session */
-bool		Log_disconnections = false;
-
 int			log_statement = LOGSTMT_NONE;
 
 /* wait N seconds to allow attach from a debugger */
@@ -3653,10 +3650,7 @@ set_debug_options(int debug_flag, GucContext context, GucSource source)
 		SetConfigOption("log_min_messages", "notice", context, source);
 
 	if (debug_flag >= 1 && context == PGC_POSTMASTER)
-	{
-		SetConfigOption("log_connections", "true", context, source);
-		SetConfigOption("log_disconnections", "true", context, source);
-	}
+		SetConfigOption("log_connections", "all", context, source);
 	if (debug_flag >= 2)
 		SetConfigOption("log_statement", "all", context, source);
 	if (debug_flag >= 3)
@@ -4271,9 +4265,10 @@ PostgresMain(const char *dbname, const char *username)
 
 	/*
 	 * Also set up handler to log session end; we have to wait till now to be
-	 * sure Log_disconnections has its final value.
+	 * sure log_connections has its final value.
 	 */
-	if (IsUnderPostmaster && Log_disconnections)
+	if (IsUnderPostmaster &&
+		(log_connections & LOG_CONNECTION_DISCONNECTED))
 		on_proc_exit(log_disconnections, 0);
 
 	pgstat_report_connect(MyDatabaseId);
 
-	if (Log_connections)
 
diff --git a/src/backend/utils/misc/guc_tables.c b/src/backend/utils/misc/guc_tables.c
index ad25cbb39c5..5b73270c8a9 100644
--- a/src/backend/utils/misc/guc_tables.c
+++ b/src/backend/utils/misc/guc_tables.c
@@ -1219,15 +1219,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."),
@@ -1238,15 +1229,6 @@ struct config_bool ConfigureNamesBool[] =
 		false,
 		NULL, NULL, NULL
 	},
-	{
-		{"log_disconnections", PGC_SU_BACKEND, LOGGING_WHAT,
-			gettext_noop("Logs end of a session, including duration."),
-			NULL
-		},
-		&Log_disconnections,
-		false,
-		NULL, NULL, NULL
-	},
 	{
 		{"log_replication_commands", PGC_SUSET, LOGGING_WHAT,
 			gettext_noop("Logs each replication command."),
@@ -4850,6 +4832,17 @@ struct config_string ConfigureNamesString[] =
 		check_debug_io_direct, assign_debug_io_direct, NULL
 	},
 
+	{
+			gettext_noop("Logs information about events during connection establishment."),
+		"",
index 5362ff80519..bf611317b3f 100644
@@ -578,8 +578,7 @@
-#log_disconnections = off
+#log_connections = ''
 #log_hostname = off
index b6a3f275a1b..ffa30e94aff 100644
@@ -143,4 +144,17 @@ typedef enum DispatchOption

+/*
+ * These flags correspond to the various stages of connection establishment
+ * which may be logged. check_log_connections() converts the options specified
+ * in the log_connections GUC to some combination of these values.
+ */
+typedef enum ConnectionLogOption
+{
+	LOG_CONNECTION_RECEIVED = (1 << 0),
+	LOG_CONNECTION_AUTHENTICATED = (1 << 1),
+	LOG_CONNECTION_AUTHORIZED = (1 << 2),
+	LOG_CONNECTION_DISCONNECTED = (1 << 3),
+} ConnectionLogOption;
+
 #endif							/* _POSTMASTER_H */
diff --git a/src/include/tcop/tcopprot.h b/src/include/tcop/tcopprot.h
index a62367f7793..dde9b7e9b59 100644
--- a/src/include/tcop/tcopprot.h
+++ b/src/include/tcop/tcopprot.h
@@ -36,7 +36,6 @@ typedef enum
 	LOGSTMT_ALL,				/* log all statements */
 } LogStmtLevel;
 
-extern PGDLLIMPORT bool Log_disconnections;
 extern PGDLLIMPORT int log_statement;
 
 /* Flags for restrict_nonsystem_relation_kind value */
index c834fa5149a..d488aa1f1e2 100644
@@ -107,8 +107,7 @@ $node->append_conf(
 
-log_disconnections = on

 
 
 my $huge_pages_status =

 

 

 $node->safe_psql(
 
index bdf39397397..e03b963f917 100644
@@ -15,8 +15,7 @@ $node->append_conf(
-log_disconnections=on
+log_connections='all'
 ));
 
 $node->start;
index d8faa9c26c1..b05a4844b26 100644
@@ -8,7 +8,6 @@ max_prepared_transactions = 10
-log_disconnections = true
index 56989aa0b84..d155dcff036 100644
+ConnectionLogOption
 ConnectionStateEnum
 ConsiderSplitContext
 Const
-- 
2.34.1

From 22584b57cda98058d2a1d714cc8d45c676935d9d Mon Sep 17 00:00:00 2001
From: Melanie Plageman <[email-masked]>
Date: Thu, 27 Feb 2025 17:33:38 -0500
Subject: [PATCH v8 2/2] Add connection establishment duration logging

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

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 ClientSocket
and BackendStartupData structures instead of simply saved in backend
local memory inherited by the child process.

Reviewed-by: Bertrand Drouvot <[email-masked]>
Reviewed-by: Fujii Masao <[email-masked]>
Reviewed-by: Jelte Fennema-Nio <[email-masked]>
Reviewed-by: Jacob Champion <[email-masked]>
Reviewed-by: Guillaume Lelarge <[email-masked]>
Discussion: https://postgr.es/m/flat/CAAKRu_b_smAHK0ZjrnL5GRxnAVWujEXQWpLXYzGbmpcZd3nLYw%40mail.gmail.com
---
 doc/src/sgml/config.sgml                | 15 +++++----
 src/backend/postmaster/launch_backend.c | 45 +++++++++++++++++++++++++
 src/backend/postmaster/postmaster.c     | 10 +++++-
 src/backend/tcop/postgres.c             | 21 ++++++++++++
 src/backend/utils/init/globals.c        |  2 ++
 src/backend/utils/init/postinit.c       | 10 ++++++
 src/include/libpq/libpq-be.h            |  1 +
 src/include/miscadmin.h                 |  2 ++
 src/include/portability/instr_time.h    |  9 +++++
 src/include/postmaster/postmaster.h     | 23 +++++++++++++
 src/include/tcop/backend_startup.h      | 14 ++++++++
 src/tools/pgindent/typedefs.list        |  1 +
 12 files changed, 146 insertions(+), 7 deletions(-)

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 4d2bbb3f720..b1f38b99ee0 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -7331,12 +7331,15 @@ local0.*    /var/log/postgresql
        </para>
 
        <para>
-        May be set to <literal>''</literal> to disable connection logging,
-        <literal>'all'</literal> to log all available connection stages, or a
-        comma-separated list of specific connection stages to log. The valid
-        options are <literal>received</literal>,
-        <literal>authenticated</literal>, <literal>authorized</literal>, and
-        <literal>disconnected</literal>.
+        May be set to <literal>''</literal> to disable this logging,
+        <literal>'all'</literal> to enable all connection log message types, or
+        a comma-separated list of the specific connection log message types to
+        emit. The valid options are <literal>received</literal>,
+        <literal>authenticated</literal>, <literal>authorized</literal>,
+        <literal>disconnected</literal>, and <literal>timings</literal>. When
+        <literal>timings</literal> is specified, a message is logged the first
+        time the connection is ready for query containing connection
+        establishment durations.
        </para>
 
        <note>
index 47375e5bfaa..67fdad55414 100644

+	/* Capture time Postmaster initiates fork for logging */
+	if ((log_connections & LOG_CONNECTION_TIMINGS) &&
+		(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 +245,22 @@ 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 ((log_connections & LOG_CONNECTION_TIMINGS) &&
+			(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 +607,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;
@@ -598,6 +620,13 @@ SubPostmasterMain(int argc, char *argv[])
 	if (argc != 3)
 		elog(FATAL, "invalid subpostmaster invocation");
 
+	/*
+	 * Set the fork end time. We haven't read the GUC file yet, so we don't
+	 * know if we will use this value for logging, but getting the time is
+	 * relatively little overhead.
+	 */
+	INSTR_TIME_SET_CURRENT(fork_ended);
+
 	/* Find the entry in child_process_kinds */
 	if (strncmp(argv[1], "--forkchild=", 12) != 0)
 		elog(FATAL, "invalid subpostmaster invocation (--forkchild argument missing)");
@@ -648,6 +677,22 @@ 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 ((log_connections & LOG_CONNECTION_TIMINGS) &&
+		(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 315f5a55a34..67d388ff2d5 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -1536,7 +1536,7 @@ check_log_connections(char **newval, void **extra, GucSource source)
 	 * log_connections can be 'all', '', or a list of comma-separated options.
 	 */
 	if (pg_strcasecmp(*newval, "all") == 0)
-		effval = "received, authenticated, authorized, disconnected";
+		effval = "received, authenticated, authorized, disconnected, timings";
 
 	/* Need a modifiable copy of string */
 	rawstring = pstrdup(effval);
@@ -1559,6 +1559,8 @@ check_log_connections(char **newval, void **extra, GucSource source)
 			flags |= LOG_CONNECTION_AUTHORIZED;
 		else if (pg_strcasecmp(item, "disconnected") == 0)
 			flags |= LOG_CONNECTION_DISCONNECTED;
+		else if (pg_strcasecmp(item, "timings") == 0)
+			flags |= LOG_CONNECTION_TIMINGS;
 		else if (pg_strcasecmp(item, "all") == 0)
 		{
 			GUC_check_errdetail("Must specify \"all\" alone with no additional options, whitespace, or characters.");
@@ -3553,6 +3555,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/postgres.c b/src/backend/tcop/postgres.c
index 8b403a6cc3d..8c6fdf4bc9d 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -4147,6 +4147,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);
@@ -4602,6 +4603,26 @@ PostgresMain(const char *dbname, const char *username)
 			/* Report any recently-changed GUC options */
 			ReportChangedGUCOptions();
 
+			/*
+					INSTR_TIME_GET_DURATION_SINCE(conn_timing.creation_time);
 
index 8811f2ba3e6..6d39acffb27 100644
 
+	/* Capture authentication start time for logging */
+	if (log_connections & LOG_CONNECTION_TIMINGS)
+		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 +257,10 @@ PerformAuthentication(Port *port)
 	 */
 	disable_timeout(STATEMENT_TIMEOUT, false);
 
+	if (log_connections & LOG_CONNECTION_TIMINGS)
index 7fe92b15477..7579d96563e 100644

 /*

 
index ffa30e94aff..70818e70d2a 100644
 
 #include "lib/ilist.h"
 #include "miscadmin.h"
 
 /*
  * A struct representing an active postmaster child process.  This is used
@@ -127,6 +128,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
@@ -155,6 +177,7 @@ typedef enum ConnectionLogOption
 	LOG_CONNECTION_AUTHENTICATED = (1 << 1),
 	LOG_CONNECTION_AUTHORIZED = (1 << 2),
 	LOG_CONNECTION_DISCONNECTED = (1 << 3),
+	LOG_CONNECTION_TIMINGS = (1 << 4),
 } ConnectionLogOption;
 
index 73285611203..03192e21387 100644

@@ -37,6 +39,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;
 
index d155dcff036..c030047a107 100644
 ConnectionLogOption
 ConnectionStateEnum
+ConnectionTiming
 ConsiderSplitContext
 Const
 ConstrCheck
-- 
2.34.1

---

From: Bertrand Drouvot <[email-masked]>
Date: Mon, 3 Mar 2025 14:07:12 +0000

Hi,

On Fri, Feb 28, 2025 at 05:42:37PM -0500, Melanie Plageman wrote:
> And all of these places we have to be super
> (the global variable) in a function.

Yeah, that could be checking before calling the function (the caller would be
responsible for checking log_connections)

> But maybe I'm not thinking about it correctly. What were you imagining?

I did not imagine that much ;-) I was just seeing this code being duplicated
and just thought about to avoid the duplication. But now that I read your comments
above then I think we could just macro-ize the child_type check (as you mentioned
up-thread). That would avoid the risk to forget to update the 3 locations doing the
exact same check should we add a new child type in the game.

Regards,

---

From: Fujii Masao <[email-masked]>
Date: Tue, 4 Mar 2025 13:45:21 +0900

> set before we use it -- I fixed some issues with that.

When log_connection is empty string in postgresql.conf and I ran
"psql -d "options=-clog_connections=all"", I got the following log message.
You can see the total duration in this message is unexpected.
It looks like this happens because creation_time wasn’t collected,
as log_connections was empty before the fork.

     LOG:  connection establishment times (ms): total: 1148052469, fork: 0, authentication: 0

Regards,

---

From: Melanie Plageman <[email-masked]>
Date: Tue, 4 Mar 2025 17:47:26 -0500

> exact same check should we add a new child type in the game.

Is there a word we could use to describe what B_BACKEND and
B_WAL_SENDER have in common? They are the only backend types that will
go through the kind of external connection establishment steps (I
think), but I don't know a very accurate way to make that distinction
(which is required to come up with a useful macro name).

- Melanie

---

From: Melanie Plageman <[email-masked]>
Date: Tue, 4 Mar 2025 18:34:47 -0500

>      LOG:  connection establishment times (ms): total: 1148052469, fork: 0, authentication: 0

Wow, yes, thanks for catching that. I didn't remember that you could
pass startup options like that. For that example,
process_startup_options() actually happens so late that we do not have
the intended value of log_connections until after we've already taken
all of the timings. As such, I propose we take those measurements
unconditionally (since we established they aren't too expensive when
compared to the cost of actually forking the backend) and then only
emit the message if log_connections is "timings". We are guaranteed to
have the intended value of log_connections by the time we are
ready-for-query. I've implemented this in [1].

- Melanie

[1] https://www.postgresql.org/message-id/CAAKRu_aoerKAOYKkc7-JGq2bixrYTbViK_7EeLNhFUGoT_omFw%40mail.gmail.com

---

From: Bertrand Drouvot <[email-masked]>
Date: Wed, 5 Mar 2025 08:53:15 +0000

Hi,

> (which is required to come up with a useful macro name).

Yeah, what about IS_CONNECTION_TIMED_BACKEND?

Regards,