From 277c32f09c35b688f0c415c758ad8d1203f2fe06 Mon Sep 17 00:00:00 2001 From: Melanie Plageman Date: Wed, 5 Mar 2025 18:05:19 -0500 Subject: [PATCH v12 2/2] Add connection establishment duration logging Add log_connections option 'ready_for_use' which logs durations of several key parts of connection establishment and setup the first time the backend is ready for query. For an 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. This logging provides visibility into authentication and fork duration as well as the end-to-end connection establishment and initialization time. To make this portable, the timings captured in the postmaster (socket creation time, fork initiation time) are passed through the BackendStartupData instead of simply saved in backend local memory. Author: Melanie Plageman 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 | 9 ++++ src/backend/postmaster/launch_backend.c | 35 ++++++++++++++ src/backend/postmaster/postmaster.c | 6 +++ src/backend/tcop/backend_startup.c | 4 ++ src/backend/tcop/postgres.c | 35 ++++++++++++++ src/backend/utils/init/postinit.c | 6 +++ src/include/miscadmin.h | 7 +++ src/include/tcop/backend_startup.h | 56 +++++++++++++++++++++-- src/include/utils/timestamp.h | 9 ++++ src/test/authentication/t/001_password.pl | 15 +++++- src/tools/pgindent/typedefs.list | 1 + 11 files changed, 179 insertions(+), 4 deletions(-) diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index fcfa7349e48..b5288132063 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -7362,6 +7362,15 @@ local0.* /var/log/postgresql + + ready_for_use + + Logs the duration of connection establishment and setup as well as + several establishment component durations. At this point, the + backend is ready for use. + + + all diff --git a/src/backend/postmaster/launch_backend.c b/src/backend/postmaster/launch_backend.c index 47375e5bfaa..44c8705424d 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 process creation for logging */ + if (IsConnectionBackend(child_type)) + ((BackendStartupData *) startup_data)->fork_started = 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 */ { + /* Capture and transfer timings that may be needed for logging */ + if (IsConnectionBackend(child_type)) + { + conn_timing.socket_create = + ((BackendStartupData *) startup_data)->socket_created; + conn_timing.fork_start = + ((BackendStartupData *) startup_data)->fork_started; + conn_timing.fork_end = GetCurrentTimestamp(); + } + /* Close the postmaster's sockets */ ClosePostmasterPorts(child_type == B_LOGGER); @@ -586,11 +600,19 @@ SubPostmasterMain(int argc, char *argv[]) char *child_kind; BackendType child_type; bool found = false; + TimestampTz fork_end; /* In EXEC_BACKEND case we will not have inherited these settings */ IsPostmasterEnvironment = true; whereToSendOutput = DestNone; + /* + * Capture the end of process creation for logging. We don't include the + * time spent copying data from shared memory and setting up the backend + * as a proper postmaster child. + */ + fork_end = GetCurrentTimestamp(); + /* Setup essential subsystems (to ensure elog() behaves sanely) */ InitializeGUCOptions(); @@ -615,6 +637,9 @@ SubPostmasterMain(int argc, char *argv[]) if (!found) elog(ERROR, "unknown child kind %s", child_kind); + if (IsConnectionBackend(child_type)) + conn_timing.fork_end = GetCurrentTimestamp(); + /* Read in the variables file */ read_backend_variables(argv[2], &startup_data, &startup_data_len); @@ -648,6 +673,16 @@ SubPostmasterMain(int argc, char *argv[]) /* Read in remaining GUC variables */ read_nondefault_variables(); + /* Capture and transfer timings that may be needed for log_connections */ + if (IsConnectionBackend(child_type)) + { + conn_timing.socket_create = + ((BackendStartupData *) startup_data)->socket_created; + conn_timing.fork_start = + ((BackendStartupData *) startup_data)->fork_started; + conn_timing.fork_end = fork_end; + } + /* * 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 b4f34c57a1b..57155c00e01 100644 --- a/src/backend/postmaster/postmaster.c +++ b/src/backend/postmaster/postmaster.c @@ -3477,6 +3477,12 @@ BackendStartup(ClientSocket *client_sock) BackendStartupData startup_data; CAC_state cac; + /* + * Capture time that Postmaster got a socket from accept (for logging + * connection establishment and setup total duration). + */ + startup_data.socket_created = GetCurrentTimestamp(); + /* * 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 c56dc1a367e..b4263d6f5cb 100644 --- a/src/backend/tcop/backend_startup.c +++ b/src/backend/tcop/backend_startup.c @@ -46,6 +46,9 @@ bool Trace_connection_negotiation = false; uint32 log_connections = 0; char *log_connections_string = NULL; +/* Other globals */ +ConnectionTiming conn_timing = {0}; + static void BackendInitialize(ClientSocket *client_sock, CAC_state cac); static int ProcessSSLStartup(Port *port); static int ProcessStartupPacket(Port *port, bool ssl_done, bool gss_done); @@ -1002,6 +1005,7 @@ validate_log_connections_options(List *elemlist, uint32 *flags) {"received", LOG_CONNECTION_RECEIVED}, {"authenticated", LOG_CONNECTION_AUTHENTICATED}, {"authorized", LOG_CONNECTION_AUTHORIZED}, + {"ready_for_use", LOG_CONNECTION_READY_FOR_USE}, {"all", LOG_CONNECTION_ALL}, }; diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c index 947ffb40421..801e9e11fff 100644 --- a/src/backend/tcop/postgres.c +++ b/src/backend/tcop/postgres.c @@ -66,6 +66,7 @@ #include "storage/proc.h" #include "storage/procsignal.h" #include "storage/sinval.h" +#include "tcop/backend_startup.h" #include "tcop/fastpath.h" #include "tcop/pquery.h" #include "tcop/tcopprot.h" @@ -4153,6 +4154,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 +4609,39 @@ 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_READY_FOR_USE) && + IsConnectionBackend(MyBackendType)) + { + uint64 total_duration, + fork_duration, + auth_duration; + + conn_timing.ready_for_use = GetCurrentTimestamp(); + + total_duration = + TimestampDifferenceMicroseconds(conn_timing.socket_create, + conn_timing.ready_for_use); + fork_duration = + TimestampDifferenceMicroseconds(conn_timing.fork_start, + conn_timing.fork_end); + auth_duration = + TimestampDifferenceMicroseconds(conn_timing.auth_start, + conn_timing.auth_end); + + ereport(LOG, + errmsg("connection ready for use: time spent (ms): total=%.3f, process creation=%.3f, authentication=%.3f", + (double) total_duration / NS_PER_US, + (double) fork_duration / NS_PER_US, + (double) auth_duration / NS_PER_US)); + + reported_first_ready_for_query = true; + } ReadyForQuery(whereToSendOutput); send_ready_for_query = false; } diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c index dc6484bb092..9e7c2b8f02f 100644 --- a/src/backend/utils/init/postinit.c +++ b/src/backend/utils/init/postinit.c @@ -195,6 +195,9 @@ PerformAuthentication(Port *port) /* This should be set already, but let's make sure */ ClientAuthInProgress = true; /* limit visibility of log messages */ + /* Capture authentication start time for logging */ + conn_timing.auth_start = 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. @@ -253,6 +256,9 @@ PerformAuthentication(Port *port) */ disable_timeout(STATEMENT_TIMEOUT, false); + /* Capture authentication end time for logging */ + conn_timing.auth_end = GetCurrentTimestamp(); + if (log_connections & LOG_CONNECTION_AUTHORIZED) { StringInfoData logmsg; diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h index a2b63495eec..6deffd0a202 100644 --- a/src/include/miscadmin.h +++ b/src/include/miscadmin.h @@ -394,6 +394,13 @@ extern PGDLLIMPORT BackendType MyBackendType; (AmAutoVacuumLauncherProcess() || \ AmLogicalSlotSyncWorkerProcess()) +/* + * Backend types that are spawned by the postmaster to serve a client + * connection. + */ +#define IsConnectionBackend(backend_type) \ + (backend_type == B_BACKEND || backend_type == B_WAL_SENDER) + extern const char *GetBackendTypeDesc(BackendType backendType); extern void SetDatabasePath(const char *path); diff --git a/src/include/tcop/backend_startup.h b/src/include/tcop/backend_startup.h index 7630f0907a0..8216a0a6a74 100644 --- a/src/include/tcop/backend_startup.h +++ b/src/include/tcop/backend_startup.h @@ -14,11 +14,16 @@ #ifndef BACKEND_STARTUP_H #define BACKEND_STARTUP_H +#include "utils/timestamp.h" + /* GUCs */ extern PGDLLIMPORT bool Trace_connection_negotiation; extern PGDLLIMPORT uint32 log_connections; extern PGDLLIMPORT char *log_connections_string; +/* Other globals */ +extern PGDLLIMPORT struct ConnectionTiming conn_timing; + /* * CAC_state is passed from postmaster to the backend process, to indicate * whether the connection should be accepted, or if the process should just @@ -39,13 +44,26 @@ typedef enum CAC_state typedef struct BackendStartupData { CAC_state canAcceptConnections; + + /* + * Time at which the connection client socket is created. Only used for + * client and wal sender connections. + */ + TimestampTz socket_created; + + /* + * Time at which the postmaster initiates process creation -- either + * through fork or otherwise. Only used for client and wal sender + * connections. + */ + TimestampTz fork_started; } BackendStartupData; /* * Granular control over which messages to log for the log_connections GUC. * - * RECEIVED, AUTHENTICATED, and AUTHORIZED are different stages of connection - * establishment and setup where we may emit a log message. + * RECEIVED, AUTHENTICATED, AUTHORIZED, and READY_FOR_USE are different stages + * of connection establishment and setup where we may emit a log message. * * ALL is a convenience alias for when all stages should be logged. * @@ -59,14 +77,46 @@ typedef enum LogConnectionOption LOG_CONNECTION_RECEIVED = (1 << 0), LOG_CONNECTION_AUTHENTICATED = (1 << 1), LOG_CONNECTION_AUTHORIZED = (1 << 2), + LOG_CONNECTION_READY_FOR_USE = (1 << 3), LOG_CONNECTION_ON = LOG_CONNECTION_RECEIVED | LOG_CONNECTION_AUTHENTICATED | LOG_CONNECTION_AUTHORIZED, LOG_CONNECTION_ALL = - LOG_CONNECTION_ON, + LOG_CONNECTION_ON | + LOG_CONNECTION_READY_FOR_USE, } LogConnectionOption; +/* + * A collection of timings and durations of various stages of connection + * establishment and setup for client backends and WAL senders. + * + * Used to emit log messages according to the options specified in the + * log_connections GUC. + */ +typedef struct ConnectionTiming +{ + /* + * The time at which the client socket is created and the time at which + * the connection is fully set up and first ready for query. Together + * these represent the total connection establishment and setup time. + */ + TimestampTz socket_create; + TimestampTz ready_for_use; + + /* Time at which process creation was initiated */ + TimestampTz fork_start; + + /* Time at which process creation was completed */ + TimestampTz fork_end; + + /* Time at which authentication started */ + TimestampTz auth_start; + + /* Time at which authentication was finished */ + TimestampTz auth_end; +} ConnectionTiming; + extern void BackendMain(const void *startup_data, size_t startup_data_len) pg_attribute_noreturn(); #endif /* BACKEND_STARTUP_H */ diff --git a/src/include/utils/timestamp.h b/src/include/utils/timestamp.h index 9963bddc0ec..8c205859c3b 100644 --- a/src/include/utils/timestamp.h +++ b/src/include/utils/timestamp.h @@ -85,6 +85,15 @@ IntervalPGetDatum(const Interval *X) #define TimestampTzPlusMilliseconds(tz,ms) ((tz) + ((ms) * (int64) 1000)) #define TimestampTzPlusSeconds(tz,s) ((tz) + ((s) * (int64) 1000000)) +/* Helper for simple subtraction between two timestamps */ +static inline uint64 +TimestampDifferenceMicroseconds(TimestampTz start_time, + TimestampTz stop_time) +{ + if (start_time >= stop_time) + return 0; + return (uint64) stop_time - start_time; +} /* Set at postmaster start */ extern PGDLLIMPORT TimestampTz PgStartTime; diff --git a/src/test/authentication/t/001_password.pl b/src/test/authentication/t/001_password.pl index e2a201ebb3f..33cf14e6529 100644 --- a/src/test/authentication/t/001_password.pl +++ b/src/test/authentication/t/001_password.pl @@ -68,8 +68,19 @@ $node->start; # Test behavior of log_connections GUC +$node->connect_ok("", + "log_connections 'on' works as expected for backwards compatibility", + log_like => [ + qr/connection received/, + qr/connection authenticated/, + qr/connection authorized/, + ], + log_unlike => [ + qr/connection ready for use/, + ],); + $node->safe_psql('postgres', - q[ALTER SYSTEM SET log_connections = received,authorized; + q[ALTER SYSTEM SET log_connections = received,authorized,ready_for_use; SELECT pg_reload_conf();]); $node->connect_ok("", @@ -77,6 +88,7 @@ $node->connect_ok("", log_like => [ qr/connection received/, qr/connection authorized/, + qr/connection ready for use/, ], log_unlike => [ qr/connection authenticated/, @@ -91,6 +103,7 @@ $node->connect_ok("", qr/connection received/, qr/connection authenticated/, qr/connection authorized/, + qr/connection ready for use/, ],); # could fail in FIPS mode diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list index 29e52b64994..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 -- 2.34.1