From 22584b57cda98058d2a1d714cc8d45c676935d9d Mon Sep 17 00:00:00 2001 From: Melanie Plageman 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. 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 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 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 | 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 - May be set to '' to disable connection logging, - 'all' to log all available connection stages, or a - comma-separated list of specific connection stages to log. The valid - options are received, - authenticated, authorized, and - disconnected. + May be set to '' to disable this logging, + 'all' 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 received, + authenticated, authorized, + disconnected, and timings. When + timings is specified, a message is logged the first + time the connection is ready for query containing connection + establishment durations. diff --git a/src/backend/postmaster/launch_backend.c b/src/backend/postmaster/launch_backend.c index 47375e5bfaa..67fdad55414 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_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(); + /* + * 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(conn_timing.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..6d39acffb27 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 (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); + /* Calculate authentication duration for logging */ + if (log_connections & LOG_CONNECTION_TIMINGS) + 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..7579d96563e 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" /* 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 ffa30e94aff..70818e70d2a 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,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; #endif /* _POSTMASTER_H */ diff --git a/src/include/tcop/backend_startup.h b/src/include/tcop/backend_startup.h index 73285611203..03192e21387 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,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; 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 d155dcff036..c030047a107 100644 --- a/src/tools/pgindent/typedefs.list +++ b/src/tools/pgindent/typedefs.list @@ -485,6 +485,7 @@ ConnStatusType ConnType ConnectionLogOption ConnectionStateEnum +ConnectionTiming ConsiderSplitContext Const ConstrCheck -- 2.34.1