From 570f72f4bc1eb71216f898246d4c752034422c24 Mon Sep 17 00:00:00 2001 From: Melanie Plageman Date: Tue, 3 Dec 2024 18:02:15 -0500 Subject: [PATCH v2] 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(+) 34.0% src/backend/postmaster/ 28.4% src/backend/tcop/ 10.5% src/backend/utils/adt/ 13.0% src/backend/utils/init/ 3.3% src/include/postmaster/ 3.4% src/include/utils/ 6.5% src/include/ diff --git a/src/backend/postmaster/launch_backend.c b/src/backend/postmaster/launch_backend.c index a97a1eda6da..009c4083906 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 5f615d0f605..b60f5d4c7d8 100644 --- a/src/backend/postmaster/postmaster.c +++ b/src/backend/postmaster/postmaster.c @@ -1676,7 +1676,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) @@ -3458,6 +3465,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 5655348a2e2..cbd952f2405 100644 --- a/src/backend/tcop/postgres.c +++ b/src/backend/tcop/postgres.c @@ -4151,6 +4151,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); @@ -4605,6 +4606,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 ba9bae05069..67827613bfc 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 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 01bb6a410cb..38aba9d3435 100644 --- a/src/backend/utils/init/postinit.c +++ b/src/backend/utils/init/postinit.c @@ -189,9 +189,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. @@ -250,6 +256,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 2f6c29200ba..3898735267c 100644 --- a/src/include/libpq/libpq-be.h +++ b/src/include/libpq/libpq-be.h @@ -252,6 +252,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 d016a9c9248..76dd27de26d 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); @@ -379,6 +381,7 @@ extern PGDLLIMPORT BackendType MyBackendType; #define AmRegularBackendProcess() (MyBackendType == B_BACKEND) #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 188a06e2379..6826e1532c3 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 01baf4aad75..b08521c2043 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 d26f023fb87..90b64b45dc5 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 d5aa5c295ae..29fc1bba01a 100644 --- a/src/tools/pgindent/typedefs.list +++ b/src/tools/pgindent/typedefs.list @@ -480,6 +480,7 @@ ConnParams ConnStatusType ConnType ConnectionStateEnum +ConnectionTiming ConsiderSplitContext Const ConstrCheck -- 2.34.1