On Wed, Feb 26, 2025 at 1:45 PM Melanie Plageman <melanieplage...@gmail.com> wrote: > > Thanks for the continued review! > > On Wed, Feb 26, 2025 at 2:41 AM Bertrand Drouvot > <bertranddrouvot...@gmail.com> wrote: > > > Add a few words in the log_connections GUC doc? (anyway we will have to if > > Fujii-san idea above about the timing is implemented) > > I forgot to do this in v5 attached in [1]. Let me go ahead and do this next.
I took a stab at this in attached v6. I feel that what I have is a bit stilted, but I'm not sure how to fix it. - Melanie
From 990f6841c3a6795d315821278d985cf0c5632f5e Mon Sep 17 00:00:00 2001 From: Melanie Plageman <melanieplage...@gmail.com> Date: Tue, 25 Feb 2025 13:08:48 -0500 Subject: [PATCH v6] Add connection establishment duration logging Add durations for several key parts of connection establishment when log_connections is enabled. 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 time with logging. To make this portable, the timestamps 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 <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 ci-os-only: --- doc/src/sgml/config.sgml | 1 + src/backend/postmaster/launch_backend.c | 23 +++++++++++++++++++++++ src/backend/postmaster/postmaster.c | 8 ++++++++ src/backend/tcop/postgres.c | 21 +++++++++++++++++++++ src/backend/utils/init/globals.c | 2 ++ src/backend/utils/init/postinit.c | 12 ++++++++++++ src/include/libpq/libpq-be.h | 2 ++ src/include/miscadmin.h | 2 ++ src/include/portability/instr_time.h | 9 +++++++++ src/include/postmaster/postmaster.h | 7 +++++++ src/include/tcop/backend_startup.h | 5 +++++ src/tools/pgindent/typedefs.list | 1 + 12 files changed, 93 insertions(+) diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index e55700f35b8..4861796654b 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -7325,6 +7325,7 @@ local0.* /var/log/postgresql Causes each attempted connection to the server to be logged, as well as successful completion of both client authentication (if necessary) and authorization. + Successful connections log the connection establishment duration. 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. diff --git a/src/backend/postmaster/launch_backend.c b/src/backend/postmaster/launch_backend.c index 47375e5bfaa..c482cb299f7 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 && + (child_type == B_BACKEND || child_type == B_WAL_SENDER)) + INSTR_TIME_SET_CURRENT(((BackendStartupData *) startup_data)->fork_time); + #ifdef EXEC_BACKEND pid = internal_forkexec(child_process_kinds[child_type].name, child_slot, startup_data, startup_data_len, client_sock); @@ -240,6 +245,15 @@ postmaster_child_launch(BackendType child_type, int child_slot, pid = fork_process(); if (pid == 0) /* child */ { + /* Calculate total fork duration in child backend for logging */ + if (Log_connections && + (child_type == B_BACKEND || child_type == B_WAL_SENDER)) + { + instr_time fork_time = ((BackendStartupData *) startup_data)->fork_time; + + conn_timing.fork_duration = INSTR_TIME_GET_DURATION_SINCE(fork_time); + } + /* Close the postmaster's sockets */ ClosePostmasterPorts(child_type == B_LOGGER); @@ -618,6 +632,15 @@ SubPostmasterMain(int argc, char *argv[]) /* Read in the variables file */ read_backend_variables(argv[2], &startup_data, &startup_data_len); + /* Calculate total fork duration in child backend for logging */ + if (Log_connections && + (child_type == B_BACKEND || child_type == B_WAL_SENDER)) + { + instr_time fork_time = ((BackendStartupData *) startup_data)->fork_time; + + conn_timing.fork_duration = INSTR_TIME_GET_DURATION_SINCE(fork_time); + } + /* Close the postmaster's sockets (as soon as we know them) */ ClosePostmasterPorts(child_type == B_LOGGER); diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c index 5dd3b6a4fd4..880f491a9f7 100644 --- a/src/backend/postmaster/postmaster.c +++ b/src/backend/postmaster/postmaster.c @@ -1685,7 +1685,14 @@ ServerLoop(void) ClientSocket s; if (AcceptConnection(events[i].fd, &s) == STATUS_OK) + { + /* + * Capture time that Postmaster got a socket from accept + * (for logging connection establishment duration) + */ + INSTR_TIME_SET_CURRENT(s.creation_time); BackendStartup(&s); + } /* We no longer need the open socket in this process */ if (s.sock != PGINVALID_SOCKET) @@ -3511,6 +3518,7 @@ BackendStartup(ClientSocket *client_sock) /* Pass down canAcceptConnections state */ startup_data.canAcceptConnections = cac; + INSTR_TIME_SET_ZERO(startup_data.fork_time); bn->rw = NULL; /* Hasn't asked to be notified about any bgworkers yet */ diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c index f2f75aa0f88..61d4ae2474d 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 && + (AmRegularBackendProcess() || AmWalSenderProcess())) + { + instr_time total_duration = + INSTR_TIME_GET_DURATION_SINCE(MyClientSocket->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 318600d6d02..30eed2e85f7 100644 --- a/src/backend/utils/init/postinit.c +++ b/src/backend/utils/init/postinit.c @@ -190,9 +190,16 @@ 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 && + (AmRegularBackendProcess() || AmWalSenderProcess())) + 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 +258,11 @@ PerformAuthentication(Port *port) */ disable_timeout(STATEMENT_TIMEOUT, false); + /* Calculate authentication duration for logging */ + if (Log_connections && + (AmRegularBackendProcess() || AmWalSenderProcess())) + conn_timing.auth_duration = INSTR_TIME_GET_DURATION_SINCE(auth_start_time); + if (Log_connections) { StringInfoData logmsg; diff --git a/src/include/libpq/libpq-be.h b/src/include/libpq/libpq-be.h index 7fe92b15477..b16ad69efff 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" /* @@ -252,6 +253,7 @@ typedef struct ClientSocket { pgsocket sock; /* File descriptor */ SockAddr raddr; /* remote addr (client) */ + instr_time creation_time; } ClientSocket; #ifdef USE_SSL 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..71a3f5f644d 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 @@ -126,6 +127,12 @@ extern PMChild *AllocDeadEndChild(void); extern bool ReleasePostmasterChildSlot(PMChild *pmchild); extern PMChild *FindPostmasterChildByPid(int pid); +typedef struct ConnectionTiming +{ + instr_time fork_duration; + 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..7d9c43ce77b 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,9 @@ typedef enum CAC_state typedef struct BackendStartupData { CAC_state canAcceptConnections; + + /* Time at which the postmaster initiates a fork of a backend process */ + instr_time fork_time; } 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 cfbab589d61..566b0d8d73b 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
