Thanks for the review!
On Tue, Feb 25, 2025 at 11:46 PM Fujii Masao
<masao.fu...@oss.nttdata.com> wrote:
>
> On 2025/02/26 6:36, Melanie Plageman wrote:
> > On Tue, Feb 25, 2025 at 3:23 PM Melanie Plageman
> > <melanieplage...@gmail.com> wrote:
>
> + /* Capture time Postmaster initiates fork for logging */
> + if (child_type == B_BACKEND)
> + INSTR_TIME_SET_CURRENT(((BackendStartupData *)
> startup_data)->fork_time);
>
> 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?
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?
> 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?
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.
> + 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,
>
> 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 <melanieplage...@gmail.com>
Date: Tue, 25 Feb 2025 13:08:48 -0500
Subject: [PATCH v5] Add connection establishment duration logging
Add durations for several key parts of connection establishment when
log_connections is enabled.
For a new incoming connection, starting from when the postmaster gets a
socket from accept() and ending when the forked child backend is first
ready for query, there are multiple steps that could each take longer
than expected due to external factors. Provide visibility into
authentication and fork duration as well as the end-to-end connection
establishment time with logging.
To make this portable, the timestamps captured in the postmaster (socket
creation time, fork initiation time) are passed through the ClientSocket
and BackendStartupData structures instead of simply saved in backend
local memory inherited by the child process.
Reviewed-by: Bertrand Drouvot <bertranddrouvot...@gmail.com>
Reviewed-by: Fujii Masao <masao.fu...@oss.nttdata.com>
Reviewed-by: Jelte Fennema-Nio <postg...@jeltef.nl>
Reviewed-by: Jacob Champion <jacob.champ...@enterprisedb.com>
Reviewed-by: Guillaume Lelarge <guillaume.lela...@dalibo.com>
Discussion: https://postgr.es/m/flat/CAAKRu_b_smAHK0ZjrnL5GRxnAVWujEXQWpLXYzGbmpcZd3nLYw%40mail.gmail.com
---
src/backend/postmaster/launch_backend.c | 23 +++++++++++++++++++++++
src/backend/postmaster/postmaster.c | 8 ++++++++
src/backend/tcop/postgres.c | 21 +++++++++++++++++++++
src/backend/utils/init/globals.c | 2 ++
src/backend/utils/init/postinit.c | 12 ++++++++++++
src/include/libpq/libpq-be.h | 2 ++
src/include/miscadmin.h | 2 ++
src/include/portability/instr_time.h | 9 +++++++++
src/include/postmaster/postmaster.h | 7 +++++++
src/include/tcop/backend_startup.h | 5 +++++
src/tools/pgindent/typedefs.list | 1 +
11 files changed, 92 insertions(+)
diff --git a/src/backend/postmaster/launch_backend.c b/src/backend/postmaster/launch_backend.c
index 47375e5bfaa..c482cb299f7 100644
--- a/src/backend/postmaster/launch_backend.c
+++ b/src/backend/postmaster/launch_backend.c
@@ -232,6 +232,11 @@ postmaster_child_launch(BackendType child_type, int child_slot,
Assert(IsPostmasterEnvironment && !IsUnderPostmaster);
+ /* Capture time Postmaster initiates fork for logging */
+ if (Log_connections &&
+ (child_type == B_BACKEND || child_type == B_WAL_SENDER))
+ INSTR_TIME_SET_CURRENT(((BackendStartupData *) startup_data)->fork_time);
+
#ifdef EXEC_BACKEND
pid = internal_forkexec(child_process_kinds[child_type].name, child_slot,
startup_data, startup_data_len, client_sock);
@@ -240,6 +245,15 @@ postmaster_child_launch(BackendType child_type, int child_slot,
pid = fork_process();
if (pid == 0) /* child */
{
+ /* Calculate total fork duration in child backend for logging */
+ if (Log_connections &&
+ (child_type == B_BACKEND || child_type == B_WAL_SENDER))
+ {
+ instr_time fork_time = ((BackendStartupData *) startup_data)->fork_time;
+
+ conn_timing.fork_duration = INSTR_TIME_GET_DURATION_SINCE(fork_time);
+ }
+
/* Close the postmaster's sockets */
ClosePostmasterPorts(child_type == B_LOGGER);
@@ -618,6 +632,15 @@ SubPostmasterMain(int argc, char *argv[])
/* Read in the variables file */
read_backend_variables(argv[2], &startup_data, &startup_data_len);
+ /* Calculate total fork duration in child backend for logging */
+ if (Log_connections &&
+ (child_type == B_BACKEND || child_type == B_WAL_SENDER))
+ {
+ instr_time fork_time = ((BackendStartupData *) startup_data)->fork_time;
+
+ conn_timing.fork_duration = INSTR_TIME_GET_DURATION_SINCE(fork_time);
+ }
+
/* Close the postmaster's sockets (as soon as we know them) */
ClosePostmasterPorts(child_type == B_LOGGER);
diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c
index 5dd3b6a4fd4..880f491a9f7 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -1685,7 +1685,14 @@ ServerLoop(void)
ClientSocket s;
if (AcceptConnection(events[i].fd, &s) == STATUS_OK)
+ {
+ /*
+ * Capture time that Postmaster got a socket from accept
+ * (for logging connection establishment duration)
+ */
+ INSTR_TIME_SET_CURRENT(s.creation_time);
BackendStartup(&s);
+ }
/* We no longer need the open socket in this process */
if (s.sock != PGINVALID_SOCKET)
@@ -3511,6 +3518,7 @@ BackendStartup(ClientSocket *client_sock)
/* Pass down canAcceptConnections state */
startup_data.canAcceptConnections = cac;
+ INSTR_TIME_SET_ZERO(startup_data.fork_time);
bn->rw = NULL;
/* Hasn't asked to be notified about any bgworkers yet */
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index f2f75aa0f88..61d4ae2474d 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -4153,6 +4153,7 @@ PostgresMain(const char *dbname, const char *username)
volatile bool send_ready_for_query = true;
volatile bool idle_in_transaction_timeout_enabled = false;
volatile bool idle_session_timeout_enabled = false;
+ bool reported_first_ready_for_query = false;
Assert(dbname != NULL);
Assert(username != NULL);
@@ -4607,6 +4608,26 @@ PostgresMain(const char *dbname, const char *username)
/* Report any recently-changed GUC options */
ReportChangedGUCOptions();
+ /*
+ * The first time this backend is ready for query, log the
+ * durations of the different components of connection
+ * establishment.
+ */
+ if (!reported_first_ready_for_query &&
+ Log_connections &&
+ (AmRegularBackendProcess() || AmWalSenderProcess()))
+ {
+ instr_time total_duration =
+ INSTR_TIME_GET_DURATION_SINCE(MyClientSocket->creation_time);
+
+ ereport(LOG,
+ errmsg("connection establishment times (ms): total: %ld, fork: %ld, authentication: %ld",
+ (long int) INSTR_TIME_GET_MILLISEC(total_duration),
+ (long int) INSTR_TIME_GET_MILLISEC(conn_timing.fork_duration),
+ (long int) INSTR_TIME_GET_MILLISEC(conn_timing.auth_duration)));
+
+ reported_first_ready_for_query = true;
+ }
ReadyForQuery(whereToSendOutput);
send_ready_for_query = false;
}
diff --git a/src/backend/utils/init/globals.c b/src/backend/utils/init/globals.c
index b844f9fdaef..3c7b14dd57d 100644
--- a/src/backend/utils/init/globals.c
+++ b/src/backend/utils/init/globals.c
@@ -43,6 +43,8 @@ volatile uint32 InterruptHoldoffCount = 0;
volatile uint32 QueryCancelHoldoffCount = 0;
volatile uint32 CritSectionCount = 0;
+ConnectionTiming conn_timing = {0};
+
int MyProcPid;
pg_time_t MyStartTime;
TimestampTz MyStartTimestamp;
diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
index 318600d6d02..30eed2e85f7 100644
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -190,9 +190,16 @@ GetDatabaseTupleByOid(Oid dboid)
static void
PerformAuthentication(Port *port)
{
+ instr_time auth_start_time;
+
/* This should be set already, but let's make sure */
ClientAuthInProgress = true; /* limit visibility of log messages */
+ /* Capture authentication start time for logging */
+ if (Log_connections &&
+ (AmRegularBackendProcess() || AmWalSenderProcess()))
+ INSTR_TIME_SET_CURRENT(auth_start_time);
+
/*
* In EXEC_BACKEND case, we didn't inherit the contents of pg_hba.conf
* etcetera from the postmaster, and have to load them ourselves.
@@ -251,6 +258,11 @@ PerformAuthentication(Port *port)
*/
disable_timeout(STATEMENT_TIMEOUT, false);
+ /* Calculate authentication duration for logging */
+ if (Log_connections &&
+ (AmRegularBackendProcess() || AmWalSenderProcess()))
+ conn_timing.auth_duration = INSTR_TIME_GET_DURATION_SINCE(auth_start_time);
+
if (Log_connections)
{
StringInfoData logmsg;
diff --git a/src/include/libpq/libpq-be.h b/src/include/libpq/libpq-be.h
index 7fe92b15477..b16ad69efff 100644
--- a/src/include/libpq/libpq-be.h
+++ b/src/include/libpq/libpq-be.h
@@ -58,6 +58,7 @@ typedef struct
#include "datatype/timestamp.h"
#include "libpq/hba.h"
#include "libpq/pqcomm.h"
+#include "portability/instr_time.h"
/*
@@ -252,6 +253,7 @@ typedef struct ClientSocket
{
pgsocket sock; /* File descriptor */
SockAddr raddr; /* remote addr (client) */
+ instr_time creation_time;
} ClientSocket;
#ifdef USE_SSL
diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h
index a2b63495eec..9dd18a2c74f 100644
--- a/src/include/miscadmin.h
+++ b/src/include/miscadmin.h
@@ -178,6 +178,8 @@ extern PGDLLIMPORT int MaxConnections;
extern PGDLLIMPORT int max_worker_processes;
extern PGDLLIMPORT int max_parallel_workers;
+extern PGDLLIMPORT struct ConnectionTiming conn_timing;
+
extern PGDLLIMPORT int commit_timestamp_buffers;
extern PGDLLIMPORT int multixact_member_buffers;
extern PGDLLIMPORT int multixact_offset_buffers;
diff --git a/src/include/portability/instr_time.h b/src/include/portability/instr_time.h
index f71a851b18d..48d7ff1bfad 100644
--- a/src/include/portability/instr_time.h
+++ b/src/include/portability/instr_time.h
@@ -184,6 +184,15 @@ GetTimerFrequency(void)
#define INSTR_TIME_ACCUM_DIFF(x,y,z) \
((x).ticks += (y).ticks - (z).ticks)
+static inline instr_time
+INSTR_TIME_GET_DURATION_SINCE(instr_time start_time)
+{
+ instr_time now;
+
+ INSTR_TIME_SET_CURRENT(now);
+ INSTR_TIME_SUBTRACT(now, start_time);
+ return now;
+}
#define INSTR_TIME_GET_DOUBLE(t) \
((double) INSTR_TIME_GET_NANOSEC(t) / NS_PER_S)
diff --git a/src/include/postmaster/postmaster.h b/src/include/postmaster/postmaster.h
index b6a3f275a1b..71a3f5f644d 100644
--- a/src/include/postmaster/postmaster.h
+++ b/src/include/postmaster/postmaster.h
@@ -15,6 +15,7 @@
#include "lib/ilist.h"
#include "miscadmin.h"
+#include "portability/instr_time.h"
/*
* A struct representing an active postmaster child process. This is used
@@ -126,6 +127,12 @@ extern PMChild *AllocDeadEndChild(void);
extern bool ReleasePostmasterChildSlot(PMChild *pmchild);
extern PMChild *FindPostmasterChildByPid(int pid);
+typedef struct ConnectionTiming
+{
+ instr_time fork_duration;
+ instr_time auth_duration;
+} ConnectionTiming;
+
/*
* These values correspond to the special must-be-first options for dispatching
* to various subprograms. parse_dispatch_option() can be used to convert an
diff --git a/src/include/tcop/backend_startup.h b/src/include/tcop/backend_startup.h
index 73285611203..7d9c43ce77b 100644
--- a/src/include/tcop/backend_startup.h
+++ b/src/include/tcop/backend_startup.h
@@ -14,6 +14,8 @@
#ifndef BACKEND_STARTUP_H
#define BACKEND_STARTUP_H
+#include "portability/instr_time.h"
+
/* GUCs */
extern PGDLLIMPORT bool Trace_connection_negotiation;
@@ -37,6 +39,9 @@ typedef enum CAC_state
typedef struct BackendStartupData
{
CAC_state canAcceptConnections;
+
+ /* Time at which the postmaster initiates a fork of a backend process */
+ instr_time fork_time;
} BackendStartupData;
extern void BackendMain(const void *startup_data, size_t startup_data_len) pg_attribute_noreturn();
diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list
index cfbab589d61..566b0d8d73b 100644
--- a/src/tools/pgindent/typedefs.list
+++ b/src/tools/pgindent/typedefs.list
@@ -484,6 +484,7 @@ ConnParams
ConnStatusType
ConnType
ConnectionStateEnum
+ConnectionTiming
ConsiderSplitContext
Const
ConstrCheck
--
2.34.1
