From 5d6947f93d8126ca5b0a86d28a7cb2e57a252b0a Mon Sep 17 00:00:00 2001 From: Melanie Plageman Date: Tue, 4 Mar 2025 09:44:34 -0500 Subject: [PATCH v9] Add connection establishment duration logging Add log_connections option 'timings' which logs durations for several key parts of connection establishment and setup 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 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 | 17 +++++++---- src/backend/libpq/auth.c | 4 +-- src/backend/postmaster/launch_backend.c | 38 +++++++++++++++++++++++++ src/backend/postmaster/postmaster.c | 8 +++++- src/backend/tcop/backend_startup.c | 4 +-- src/backend/tcop/postgres.c | 21 ++++++++++++++ src/backend/utils/init/globals.c | 2 ++ src/backend/utils/init/postinit.c | 10 ++++++- src/backend/utils/misc/guc_tables.c | 33 +++++++++++++++------ src/include/miscadmin.h | 2 ++ src/include/portability/instr_time.h | 9 ++++++ src/include/postmaster/postmaster.h | 35 ++++++++++++++++++++++- src/include/tcop/backend_startup.h | 12 ++++++++ src/tools/pgindent/typedefs.list | 2 ++ 14 files changed, 176 insertions(+), 21 deletions(-) diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index d2fa5f7d1a9..219c9ff6c5d 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -7315,20 +7315,27 @@ local0.* /var/log/postgresql - log_connections (boolean) + log_connections (enum) log_connections configuration parameter - Causes each attempted connection to the server to be logged, - as well as successful completion of both client authentication (if - necessary) and authorization. + Causes each attempted connection to the server to be logged, as well as + successful completion of both client authentication (if necessary) and + authorization. Valid values are off (the default), + on, and timings. + timings emits all the messages emitted when + log_connections is on + plus an additional message at the end of connection setup containing + durations of various stages of connection establishment and setup. + + + Only superusers and users with the appropriate SET privilege can change this parameter at session start, and it cannot be changed at all within a session. - The default is off. diff --git a/src/backend/libpq/auth.c b/src/backend/libpq/auth.c index 81e2f8184e3..041ef9ba2cf 100644 --- a/src/backend/libpq/auth.c +++ b/src/backend/libpq/auth.c @@ -349,7 +349,7 @@ set_authn_id(Port *port, const char *id) MyClientConnectionInfo.authn_id = MemoryContextStrdup(TopMemoryContext, id); MyClientConnectionInfo.auth_method = port->hba->auth_method; - if (Log_connections) + if (log_connections & LOG_CONNECTION_BASIC) { ereport(LOG, errmsg("connection authenticated: identity=\"%s\" method=%s " @@ -633,7 +633,7 @@ ClientAuthentication(Port *port) #endif } - if (Log_connections && status == STATUS_OK && + if (log_connections & LOG_CONNECTION_BASIC && status == STATUS_OK && !MyClientConnectionInfo.authn_id) { /* diff --git a/src/backend/postmaster/launch_backend.c b/src/backend/postmaster/launch_backend.c index 47375e5bfaa..2c45cbeb6d5 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 || 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 +244,21 @@ 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 (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 +605,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; @@ -615,6 +635,9 @@ SubPostmasterMain(int argc, char *argv[]) if (!found) elog(ERROR, "unknown child kind %s", child_kind); + if (child_type == B_BACKEND || child_type == B_WAL_SENDER) + INSTR_TIME_SET_CURRENT(fork_ended); + /* Read in the variables file */ read_backend_variables(argv[2], &startup_data, &startup_data_len); @@ -648,6 +671,21 @@ 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 (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 5dd3b6a4fd4..68bc5e1f49e 100644 --- a/src/backend/postmaster/postmaster.c +++ b/src/backend/postmaster/postmaster.c @@ -237,7 +237,7 @@ int PreAuthDelay = 0; int AuthenticationTimeout = 60; bool log_hostname; /* for ps display and logging */ -bool Log_connections = false; +int log_connections = 0; bool enable_bonjour = false; char *bonjour_name; @@ -3478,6 +3478,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/backend_startup.c b/src/backend/tcop/backend_startup.c index c70746fa562..da7f80c9337 100644 --- a/src/backend/tcop/backend_startup.c +++ b/src/backend/tcop/backend_startup.c @@ -201,8 +201,8 @@ BackendInitialize(ClientSocket *client_sock, CAC_state cac) port->remote_host = MemoryContextStrdup(TopMemoryContext, remote_host); port->remote_port = MemoryContextStrdup(TopMemoryContext, remote_port); - /* And now we can issue the Log_connections message, if wanted */ - if (Log_connections) + /* And now we can log that the connection was received, if enabled */ + if (log_connections & LOG_CONNECTION_BASIC) { if (remote_port[0]) ereport(LOG, diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c index f2f75aa0f88..7bdd1f708fa 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(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 ee1a9d5d98b..ad1437bb286 100644 --- a/src/backend/utils/init/postinit.c +++ b/src/backend/utils/init/postinit.c @@ -191,9 +191,14 @@ 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 */ + 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. @@ -252,7 +257,10 @@ PerformAuthentication(Port *port) */ disable_timeout(STATEMENT_TIMEOUT, false); - if (Log_connections) + /* Calculate authentication duration for logging */ + conn_timing.auth_duration = INSTR_TIME_GET_DURATION_SINCE(auth_start_time); + + if (log_connections & LOG_CONNECTION_BASIC) { StringInfoData logmsg; diff --git a/src/backend/utils/misc/guc_tables.c b/src/backend/utils/misc/guc_tables.c index ad25cbb39c5..a063cd10597 100644 --- a/src/backend/utils/misc/guc_tables.c +++ b/src/backend/utils/misc/guc_tables.c @@ -476,6 +476,20 @@ static const struct config_enum_entry wal_compression_options[] = { {NULL, 0, false} }; +static const struct config_enum_entry log_connections_options[] = { + {"off", 0, false}, + {"on", LOG_CONNECTION_BASIC, false}, + {"true", LOG_CONNECTION_BASIC, true}, + {"false", 0, true}, + {"yes", LOG_CONNECTION_BASIC, true}, + {"no", 0, true}, + {"timings", LOG_CONNECTION_TIMINGS | LOG_CONNECTION_BASIC, false}, + {"1", LOG_CONNECTION_BASIC, true}, + {"0", 0, true}, + {NULL, 0, false} +}; + + /* * Options for enum values stored in other modules */ @@ -1219,15 +1233,6 @@ struct config_bool ConfigureNamesBool[] = true, NULL, NULL, NULL }, - { - {"log_connections", PGC_SU_BACKEND, LOGGING_WHAT, - gettext_noop("Logs each successful connection."), - NULL - }, - &Log_connections, - false, - NULL, NULL, NULL - }, { {"trace_connection_negotiation", PGC_POSTMASTER, DEVELOPER_OPTIONS, gettext_noop("Logs details of pre-authentication connection handshake."), @@ -5299,6 +5304,16 @@ struct config_enum ConfigureNamesEnum[] = NULL, NULL, NULL }, + { + {"log_connections", PGC_SU_BACKEND, LOGGING_WHAT, + gettext_noop("Logs information about events during connection establishment."), + NULL, + }, + &log_connections, + 0, log_connections_options, + NULL, NULL, NULL + }, + /* End-of-list marker */ { {NULL, 0, 0, NULL, NULL}, NULL, 0, NULL, NULL, NULL, NULL 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..7ff3aa5179a 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 @@ -51,6 +52,17 @@ typedef struct extern int num_pmchild_slots; #endif + +/* + * Granular control over which messages to log for the log_connections GUC. + */ +typedef enum LogConnectionOption +{ + LOG_CONNECTION_BASIC = (1 << 0), + LOG_CONNECTION_TIMINGS = (1 << 1), +} LogConnectionOption; + + /* GUC options */ extern PGDLLIMPORT bool EnableSSL; extern PGDLLIMPORT int SuperuserReservedConnections; @@ -63,7 +75,7 @@ extern PGDLLIMPORT char *ListenAddresses; extern PGDLLIMPORT bool ClientAuthInProgress; extern PGDLLIMPORT int PreAuthDelay; extern PGDLLIMPORT int AuthenticationTimeout; -extern PGDLLIMPORT bool Log_connections; +extern PGDLLIMPORT int log_connections; extern PGDLLIMPORT bool log_hostname; extern PGDLLIMPORT bool enable_bonjour; extern PGDLLIMPORT char *bonjour_name; @@ -126,6 +138,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 diff --git a/src/include/tcop/backend_startup.h b/src/include/tcop/backend_startup.h index 73285611203..62b4746ee60 100644 --- a/src/include/tcop/backend_startup.h +++ b/src/include/tcop/backend_startup.h @@ -37,6 +37,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 9840060997f..3da74999634 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 @@ -1555,6 +1556,7 @@ LockTupleMode LockViewRecurse_context LockWaitPolicy LockingClause +LogConnectionOption LogOpts LogStmtLevel LogicalDecodeBeginCB -- 2.34.1