Hi,
Users wishing to debug slow connection establishment have little
visibility into which steps take the most time. We don't expose any
stats and none of the logging includes durations.
The attached patch logs durations for authentication, forking the
Postgres backend, and the end-to-end connection establishment duration
starting from when the postmaster calls accept() and ending the first
time the forked backend is ready for query.
As an example of how this could be useful, I artificially slowed down
authentication and you can see that that is now visible in logs:
LOG: backend ready for query. pid=86341. socket=10. connection
establishment times (ms): total: 8, fork: 0, authentication: 0
LOG: backend ready for query. pid=86794. socket=10. connection
establishment times (ms): total: 108, fork: 0, authentication: 100
Two notes on implementation:
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.
Secondly, I used TimestampTz for the times, but it is pretty unclear
to me when instr_time should be used vs TimestampTz for such things.
instr_time says it is more portable, but there are all sorts of places
that use TimestampTz that would probably need to be portable.
Also, INSTR_TIME_SUBTRACT() isn't overflow safe, which must be because
the actual data type of ticks is platform dependent and so the caller
is responsible for not passing it values that would overflow when
subtracted.
- Melanie
From f6fa312b605fac31463acc90446aad6afd6933ec Mon Sep 17 00:00:00 2001
From: Melanie Plageman <melanieplage...@gmail.com>
Date: Tue, 3 Dec 2024 18:02:15 -0500
Subject: [PATCH v1] 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.
---
src/backend/postmaster/launch_backend.c | 25 +++++++++++++++++++++++++
src/backend/postmaster/postmaster.c | 8 ++++++++
src/backend/tcop/postgres.c | 23 +++++++++++++++++++++++
src/backend/utils/adt/timestamp.c | 13 +++++++++++++
src/backend/utils/init/globals.c | 2 ++
src/backend/utils/init/postinit.c | 11 +++++++++++
src/include/libpq/libpq-be.h | 1 +
src/include/miscadmin.h | 3 +++
src/include/postmaster/postmaster.h | 7 +++++++
src/include/tcop/backend_startup.h | 3 +++
src/include/utils/timestamp.h | 3 +++
src/tools/pgindent/typedefs.list | 1 +
12 files changed, 100 insertions(+)
diff --git a/src/backend/postmaster/launch_backend.c b/src/backend/postmaster/launch_backend.c
index 1f2d829ec5a..4c3e3ced13a 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)
+ ((BackendStartupData *) startup_data)->fork_time = GetCurrentTimestamp();
+
#ifdef EXEC_BACKEND
pid = internal_forkexec(child_process_kinds[child_type].name, child_slot,
startup_data, startup_data_len, client_sock);
@@ -240,6 +244,16 @@ postmaster_child_launch(BackendType child_type, int child_slot,
pid = fork_process();
if (pid == 0) /* child */
{
+ /* Calculate total fork duration in child backend for logging */
+ if (child_type == B_BACKEND)
+ {
+ TimestampTz fork_time = ((BackendStartupData *) startup_data)->fork_time;
+ TimestampTz cur_time = GetCurrentTimestamp();
+
+ conn_timing.fork_duration = TimestampDifferenceMicroseconds(fork_time,
+ cur_time);
+ }
+
/* Close the postmaster's sockets */
ClosePostmasterPorts(child_type == B_LOGGER);
@@ -618,6 +632,17 @@ 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)
+ {
+ TimestampTz fork_time = ((BackendStartupData *) startup_data)->fork_time;
+ TimestampTz cur_time = GetCurrentTimestamp();
+
+ conn_timing.fork_duration = TimestampDifferenceMicroseconds(fork_time,
+ cur_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 6f37822c887..642dbb7d880 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -1675,7 +1675,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)
+ */
+ s.creation_time = GetCurrentTimestamp();
BackendStartup(&s);
+ }
/* We no longer need the open socket in this process */
if (s.sock != PGINVALID_SOCKET)
@@ -3383,6 +3390,7 @@ BackendStartup(ClientSocket *client_sock)
/* Pass down canAcceptConnections state */
startup_data.canAcceptConnections = cac;
+ startup_data.fork_time = 0;
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 e0a603f42bb..b1fae3cd476 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -4280,6 +4280,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);
@@ -4734,6 +4735,28 @@ 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 && AmClientBackendProcess())
+ {
+ TimestampTz cur_time = GetCurrentTimestamp();
+ TimestampTz total_duration =
+ TimestampDifferenceMicroseconds(MyClientSocket->creation_time, cur_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) total_duration / 1000,
+ (long int) conn_timing.fork_duration / 1000,
+ (long int) conn_timing.auth_duration / 1000));
+
+ reported_first_ready_for_query = true;
+ }
ReadyForQuery(whereToSendOutput);
send_ready_for_query = false;
}
diff --git a/src/backend/utils/adt/timestamp.c b/src/backend/utils/adt/timestamp.c
index 18d7d8a108a..9adaad6ef01 100644
--- a/src/backend/utils/adt/timestamp.c
+++ b/src/backend/utils/adt/timestamp.c
@@ -1769,6 +1769,19 @@ TimestampDifferenceMilliseconds(TimestampTz start_time, TimestampTz stop_time)
return (long) ((diff + 999) / 1000);
}
+/*
+ * Returns the difference between two timestamps safely as an unsigned int64.
+ */
+uint64
+TimestampDifferenceMicroseconds(TimestampTz start_time, TimestampTz stop_time)
+{
+ /* If start_time is in the future or now, no time has elapsed */
+ if (start_time >= stop_time)
+ return 0;
+
+ return (uint64) stop_time - start_time;
+}
+
/*
* TimestampDifferenceExceeds -- report whether the difference between two
* timestamps is >= a threshold (expressed in milliseconds)
diff --git a/src/backend/utils/init/globals.c b/src/backend/utils/init/globals.c
index 03a54451ac2..f38a5c34cb1 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 5b657a3f135..2c96ed56849 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)
{
+ TimestampTz auth_start_time = 0;
+
/* This should be set already, but let's make sure */
ClientAuthInProgress = true; /* limit visibility of log messages */
+ /* Capture authentication start time for logging */
+ if (AmClientBackendProcess())
+ auth_start_time = GetCurrentTimestamp();
+
/*
* 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,11 @@ PerformAuthentication(Port *port)
*/
disable_timeout(STATEMENT_TIMEOUT, false);
+ /* Calculate authentication duration for logging */
+ if (AmClientBackendProcess())
+ conn_timing.auth_duration = TimestampDifferenceMicroseconds(auth_start_time,
+ GetCurrentTimestamp());
+
if (Log_connections)
{
StringInfoData logmsg;
diff --git a/src/include/libpq/libpq-be.h b/src/include/libpq/libpq-be.h
index 9109b2c3344..f0ad28c04ec 100644
--- a/src/include/libpq/libpq-be.h
+++ b/src/include/libpq/libpq-be.h
@@ -243,6 +243,7 @@ typedef struct ClientSocket
{
pgsocket sock; /* File descriptor */
SockAddr raddr; /* remote addr (client) */
+ TimestampTz creation_time;
} ClientSocket;
#ifdef USE_SSL
diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h
index 42a2b38cac9..677afee2350 100644
--- a/src/include/miscadmin.h
+++ b/src/include/miscadmin.h
@@ -105,6 +105,8 @@ extern PGDLLIMPORT volatile uint32 InterruptHoldoffCount;
extern PGDLLIMPORT volatile uint32 QueryCancelHoldoffCount;
extern PGDLLIMPORT volatile uint32 CritSectionCount;
+extern PGDLLIMPORT struct ConnectionTiming conn_timing;
+
/* in tcop/postgres.c */
extern void ProcessInterrupts(void);
@@ -371,6 +373,7 @@ extern PGDLLIMPORT BackendType MyBackendType;
#define AmAutoVacuumLauncherProcess() (MyBackendType == B_AUTOVAC_LAUNCHER)
#define AmAutoVacuumWorkerProcess() (MyBackendType == B_AUTOVAC_WORKER)
+#define AmClientBackendProcess() (MyBackendType == B_BACKEND)
#define AmBackgroundWorkerProcess() (MyBackendType == B_BG_WORKER)
#define AmWalSenderProcess() (MyBackendType == B_WAL_SENDER)
#define AmLogicalSlotSyncWorkerProcess() (MyBackendType == B_SLOTSYNC_WORKER)
diff --git a/src/include/postmaster/postmaster.h b/src/include/postmaster/postmaster.h
index 24d49a5439e..e7562cb39b8 100644
--- a/src/include/postmaster/postmaster.h
+++ b/src/include/postmaster/postmaster.h
@@ -126,6 +126,12 @@ extern PMChild *AllocDeadEndChild(void);
extern bool ReleasePostmasterChildSlot(PMChild *pmchild);
extern PMChild *FindPostmasterChildByPid(int pid);
+typedef struct ConnectionTiming
+{
+ uint64 fork_duration;
+ uint64 auth_duration;
+} ConnectionTiming;
+
/*
* Note: MAX_BACKENDS is limited to 2^18-1 because that's the width reserved
* for buffer references in buf_internals.h. This limitation could be lifted
@@ -155,4 +161,5 @@ typedef enum DispatchOption
extern DispatchOption parse_dispatch_option(const char *name);
+
#endif /* _POSTMASTER_H */
diff --git a/src/include/tcop/backend_startup.h b/src/include/tcop/backend_startup.h
index 993b013afdd..8e248bb8666 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 "datatype/timestamp.h"
+
/* GUCs */
extern PGDLLIMPORT bool Trace_connection_negotiation;
@@ -37,6 +39,7 @@ typedef enum CAC_state
typedef struct BackendStartupData
{
CAC_state canAcceptConnections;
+ TimestampTz fork_time;
} BackendStartupData;
extern void BackendMain(char *startup_data, size_t startup_data_len) pg_attribute_noreturn();
diff --git a/src/include/utils/timestamp.h b/src/include/utils/timestamp.h
index a6ce03ed460..77014cd4fff 100644
--- a/src/include/utils/timestamp.h
+++ b/src/include/utils/timestamp.h
@@ -104,6 +104,9 @@ extern void TimestampDifference(TimestampTz start_time, TimestampTz stop_time,
long *secs, int *microsecs);
extern long TimestampDifferenceMilliseconds(TimestampTz start_time,
TimestampTz stop_time);
+
+extern uint64 TimestampDifferenceMicroseconds(TimestampTz start_time,
+ TimestampTz stop_time);
extern bool TimestampDifferenceExceeds(TimestampTz start_time,
TimestampTz stop_time,
int msec);
diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list
index ce33e55bf1d..a6792ec17a3 100644
--- a/src/tools/pgindent/typedefs.list
+++ b/src/tools/pgindent/typedefs.list
@@ -475,6 +475,7 @@ ConnParams
ConnStatusType
ConnType
ConnectionStateEnum
+ConnectionTiming
ConsiderSplitContext
Const
ConstrCheck
--
2.34.1
