From 6f7f1a2e3ea660596bee0348691e192b8c2fce24 Mon Sep 17 00:00:00 2001 From: Melanie Plageman Date: Thu, 27 Feb 2025 17:33:38 -0500 Subject: [PATCH v7 2/2] 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 Reviewed-by: Fujii Masao Reviewed-by: Jelte Fennema-Nio Reviewed-by: Jacob Champion Reviewed-by: Guillaume Lelarge 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 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. diff --git a/src/backend/postmaster/launch_backend.c b/src/backend/postmaster/launch_backend.c index 47375e5bfaa..3fe68601899 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 & LOG_CONNECTION_TIMINGS) && + (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 & LOG_CONNECTION_TIMINGS) && + (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 & LOG_CONNECTION_READY) && + (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 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; 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) @@ -3585,6 +3594,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..d753c6bbd5b 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 & LOG_CONNECTION_TIMINGS) && + (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 8811f2ba3e6..44e086ceca7 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 & LOG_CONNECTION_TIMINGS) && + (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 & LOG_CONNECTION_TIMINGS) && + (AmRegularBackendProcess() || AmWalSenderProcess())) + conn_timing.auth_duration = INSTR_TIME_GET_DURATION_SINCE(auth_start_time); + if (log_connections & LOG_CONNECTION_AUTHORIZED) { 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 adc693a6b2b..dae7551e7ad 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 @@ -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 */ 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 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