From f0040ff957176a3dec61cacc7771945e6e2ccf8d Mon Sep 17 00:00:00 2001 From: Melanie Plageman Date: Wed, 5 Mar 2025 18:05:19 -0500 Subject: [PATCH v11 2/3] Add connection establishment duration logging Add log_connections option 'ready_for_query' 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 | 39 ++++++++++++++++ src/backend/postmaster/postmaster.c | 6 +++ src/backend/tcop/backend_startup.c | 1 + src/backend/tcop/postgres.c | 22 +++++++++ src/backend/utils/init/globals.c | 3 ++ src/backend/utils/init/postinit.c | 8 ++++ src/include/miscadmin.h | 9 ++++ src/include/portability/instr_time.h | 9 ++++ src/include/tcop/backend_startup.h | 45 +++++++++++++++++-- .../postmaster/t/002_connection_limits.pl | 8 +++- src/tools/pgindent/typedefs.list | 1 + 12 files changed, 156 insertions(+), 4 deletions(-) diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index b97707a7ec2..f424b3f215b 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -7362,6 +7362,15 @@ local0.* /var/log/postgresql + + ready_for_query + + Logs the duration of connection establishment and setup as well as + several establishment component durations. At this point, the + backend is ready for query. + + + all diff --git a/src/backend/postmaster/launch_backend.c b/src/backend/postmaster/launch_backend.c index 47375e5bfaa..097605b4070 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 (IsConnectionBackend(child_type)) + 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 timing data captured by postmaster that may be + * needed for log_connections. + */ + if (IsConnectionBackend(child_type)) + { + BackendStartupData *data = (BackendStartupData *) startup_data; + + /* Calculate fork duration since we have start and end times */ + conn_timing.fork_duration = INSTR_TIME_GET_DURATION_SINCE(data->fork_started); + + /* Will be used to calculate total connection setup duration */ + 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 (IsConnectionBackend(child_type)) + INSTR_TIME_SET_CURRENT(fork_ended); + /* Read in the variables file */ read_backend_variables(argv[2], &startup_data, &startup_data_len); @@ -648,6 +671,22 @@ SubPostmasterMain(int argc, char *argv[]) /* Read in remaining GUC variables */ read_nondefault_variables(); + /* + * Transfer over any timing data captured by postmaster that may be needed + * for log_connections. + */ + if (IsConnectionBackend(child_type)) + { + BackendStartupData *data = (BackendStartupData *) startup_data; + + /* Calculate fork duration since we have start and end times */ + conn_timing.fork_duration = fork_ended; + INSTR_TIME_SUBTRACT(conn_timing.fork_duration, data->fork_started); + + /* Will be used to calculate total connection setup duration */ + 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 b4f34c57a1b..d46ffa34151 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). + */ + 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 84db47231f6..399562bb599 100644 --- a/src/backend/tcop/backend_startup.c +++ b/src/backend/tcop/backend_startup.c @@ -997,6 +997,7 @@ validate_log_connections_options(List *elemlist) {"received", LOG_CONNECTION_RECEIVED}, {"authenticated", LOG_CONNECTION_AUTHENTICATED}, {"authorized", LOG_CONNECTION_AUTHORIZED}, + {"ready_for_query", LOG_CONNECTION_READY_FOR_QUERY}, {"all", LOG_CONNECTION_ALL}, }; diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c index 947ffb40421..4e74f309c47 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,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_READY_FOR_QUERY) && + IsConnectionBackend(MyBackendType)) + { + instr_time total_duration = + INSTR_TIME_GET_DURATION_SINCE(conn_timing.creation_time); + + ereport(LOG, + errmsg("connection ready for query. durations (ms): total: %.3f, fork: %.3f, authentication: %.3f", + (double) INSTR_TIME_GET_NANOSEC(total_duration) / NS_PER_MS, + (double) INSTR_TIME_GET_NANOSEC(conn_timing.fork_duration) / NS_PER_MS, + (double) INSTR_TIME_GET_NANOSEC(conn_timing.auth_duration) / NS_PER_MS)); + + 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..9c59f31fc84 100644 --- a/src/backend/utils/init/globals.c +++ b/src/backend/utils/init/globals.c @@ -24,6 +24,7 @@ #include "miscadmin.h" #include "postmaster/postmaster.h" #include "storage/procnumber.h" +#include "tcop/backend_startup.h" ProtocolVersion FrontendProtocol; @@ -43,6 +44,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 dc6484bb092..7c1ab501395 100644 --- a/src/backend/utils/init/postinit.c +++ b/src/backend/utils/init/postinit.c @@ -192,9 +192,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. @@ -253,6 +258,9 @@ PerformAuthentication(Port *port) */ disable_timeout(STATEMENT_TIMEOUT, false); + /* Calculate authentication duration for logging */ + 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/miscadmin.h b/src/include/miscadmin.h index a2b63495eec..ec5ed2235e6 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; @@ -394,6 +396,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/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/tcop/backend_startup.h b/src/include/tcop/backend_startup.h index 66d370c1e00..d4ad9f69086 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; extern PGDLLIMPORT int log_connections; @@ -39,13 +41,25 @@ 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; /* * 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_QUERY 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. * @@ -60,14 +74,39 @@ typedef enum LogConnectionOption LOG_CONNECTION_RECEIVED = (1 << 0), LOG_CONNECTION_AUTHENTICATED = (1 << 1), LOG_CONNECTION_AUTHORIZED = (1 << 2), + LOG_CONNECTION_READY_FOR_QUERY = (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_QUERY, } 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. 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; + extern void BackendMain(const void *startup_data, size_t startup_data_len) pg_attribute_noreturn(); #endif /* BACKEND_STARTUP_H */ diff --git a/src/test/postmaster/t/002_connection_limits.pl b/src/test/postmaster/t/002_connection_limits.pl index f19d6e73ac9..de35d85e23e 100644 --- a/src/test/postmaster/t/002_connection_limits.pl +++ b/src/test/postmaster/t/002_connection_limits.pl @@ -29,11 +29,12 @@ $node->connect_ok("", qr/connection received/, qr/connection authenticated/, qr/connection authorized/, + qr/connection ready for query/, ],); $node->safe_psql( 'postgres', - q[ALTER SYSTEM SET log_connections = received,authorized; + q[ALTER SYSTEM SET log_connections = received,authorized,ready_for_query; SELECT pg_reload_conf();]); $node->connect_ok("", @@ -41,6 +42,7 @@ $node->connect_ok("", log_like => [ qr/connection received/, qr/connection authorized/, + qr/connection ready for query/, ], log_unlike => [ qr/connection authenticated/, @@ -56,6 +58,9 @@ $node->connect_ok("", qr/connection received/, qr/connection authenticated/, qr/connection authorized/, + ], + log_unlike => [ + qr/connection ready for query/, ],); $node->safe_psql( @@ -68,6 +73,7 @@ $node->connect_ok("", qr/connection received/, qr/connection authenticated/, qr/connection authorized/, + qr/connection ready for query/, ],); $node->safe_psql( 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