Attached v9 implements log_connections as an enum with a new third value "timings".
On Mon, Mar 3, 2025 at 11:14 AM Bertrand Drouvot <bertranddrouvot...@gmail.com> wrote: > > > On Fri, Feb 28, 2025 at 05:52:35PM -0500, Melanie Plageman wrote: > > > We have to be really careful about when log_connections is actually > > set before we use it -- I fixed some issues with that. > > Good catch! Yeah for the EXEC_BACKEND case we need to wait that > read_nondefault_variables() > in SubPostmasterMain() is executed. Due to this and the bug Fujii-san reported with passing options to psql (process_startup_options() is called too late for us to use the value of log_connections as a gate for getting any of the timings), I've decided to get the time regardless of the setting of log_connections. This means we can be sure to have valid values at the end when the message needs to be emitted. I was wondering if we should remove the backend type condition (B_WAL_SENDER/B_BACKEND) too. It is only guarding capturing the fork start and end time. That's just two measurements. Maybe we should just always get fork start and end time. Spending extra time in forking due to excess CPU activity (or some other reason) would be relevant for all backend types, not just wal sender and client backends. We do only want to log it in those cases, though... > +bool > +check_log_connections(char **newval, void **extra, GucSource source) > +{ > > This function is pretty close to check_debug_io_direct() for example and its > overall content, memory management, looks good to me. I just have a few > following comments about it. Yep, one more reason I think PGC_SET is a good idea. Code deduplication. > +typedef enum ConnectionLogOption > +{ > + LOG_CONNECTION_RECEIVED = (1 << 0), > + LOG_CONNECTION_AUTHENTICATED = (1 << 1), > + LOG_CONNECTION_AUTHORIZED = (1 << 2), > + LOG_CONNECTION_DISCONNECTED = (1 << 3), > +} ConnectionLogOption; > > I wonder if it would make sense to add LOG_CONNECTION_ALL here > (LOG_CONNECTION_RECEIVED | LOG_CONNECTION_AUTHENTICATED ..) > > That sounds a better place (than defining "all" in check_log_connections()) to > me. It's also how it is done in MonotonicFunction. The attached patch doesn't work exactly the same because it is a regular enum and not a string list (so no "all"), but I do still have a LogConnectionOption. The user interface is that timings includes all the same messages as "on", however for the enum, I've defined it like this: typedef enum LogConnectionOption { LOG_CONNECTION_BASIC = (1 << 0), LOG_CONNECTION_TIMINGS = (1 << 1), } LogConnectionOption; and then in the enum array, I have this static const struct config_enum_entry log_connections_options[] = { {"timings", LOG_CONNECTION_TIMINGS | LOG_CONNECTION_BASIC, false}, This is in contrast to MonotonicFunction which defines MONOTONICFUNC_BOTH as including both values in the enum typedef enum MonotonicFunction { MONOTONICFUNC_NONE = 0, MONOTONICFUNC_INCREASING = (1 << 0), MONOTONICFUNC_DECREASING = (1 << 1), MONOTONICFUNC_BOTH = MONOTONICFUNC_INCREASING | MONOTONICFUNC_DECREASING, } MonotonicFunction; I think the way I've done it makes sense because the "business logic" of how "timings" includes all the messages from "on" doesn't have to pollute the code and doesn't take away our ability to use the enum values independently. When I want to emit a regular logging message, I can just check if (log_connections & LOG_CONNECTION_BASIC) which will work for "timings" too, but without taking away the flexibility to use the enum values discretely. > Also not sure if it's worth adding a "MAX" (like it's done for relopt_kind) > because we'd probably not go over it anyay. > > " > /* some compilers treat enums as signed ints, so we can't use 1 << 31 */ > RELOPT_KIND_MAX = (1 << 30) That actually seems kind of broken -- what if it is on a platform where integers are 16 bits? Maybe we don't support any of those. Honestly I find the MAX more confusing than not having it at all. I think we have to assume that programmers know or can look up how many bits they can use of an enum in C. Or we can just upgrade to c23 and have explicit underlying types for enums! :) > s/ConnectionLogOption/LogConnectionOption/? (as it is linked to > "log_connections") Yep. Good idea. I've changed this. > All the TAP tests have been modified that way: > > -$node->append_conf('postgresql.conf', "log_connections = on"); > +$node->append_conf('postgresql.conf', "log_connections = 'all'"); > > Is it worh to add some checks for the other values? Now we are back to only having 3 values, but I was thinking if we wanted to add some test exercising "timings". We can't test any specific values of any of the durations emitted, so it would have to just be a test that that log message was emitted. I don't see a very good place to add such a test though. There is src/test/postmaster/t/002_connection_limits.pl -- which has to do with testing different connection limits (like max_connections). I don't see any other TAP tests that are testing connections. There are a whole bunch of auth tests, I suppose. > I did a few manual checks and that seems to work as expected. Thanks so much for your continued feedback and review! - Melanie
From 5d6947f93d8126ca5b0a86d28a7cb2e57a252b0a Mon Sep 17 00:00:00 2001 From: Melanie Plageman <melanieplage...@gmail.com> 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 <bertranddrouvot...@gmail.com> Reviewed-by: Fujii Masao <masao.fu...@oss.nttdata.com> Reviewed-by: Jelte Fennema-Nio <postg...@jeltef.nl> Reviewed-by: Jacob Champion <jacob.champ...@enterprisedb.com> Reviewed-by: Guillaume Lelarge <guillaume.lela...@dalibo.com> 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 </varlistentry> <varlistentry id="guc-log-connections" xreflabel="log_connections"> - <term><varname>log_connections</varname> (<type>boolean</type>) + <term><varname>log_connections</varname> (<type>enum</type>) <indexterm> <primary><varname>log_connections</varname> configuration parameter</primary> </indexterm> </term> <listitem> <para> - 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 <literal>off</literal> (the default), + <literal>on</literal>, and <literal>timings</literal>. + <literal>timings</literal> emits all the messages emitted when + <structfield>log_connections</structfield> is <literal>on</literal> + plus an additional message at the end of connection setup containing + durations of various stages of connection establishment and setup. + </para> + + <para> Only superusers and users with the appropriate <literal>SET</literal> privilege can change this parameter at session start, and it cannot be changed at all within a session. - The default is <literal>off</literal>. </para> <note> 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