Add connection establishment duration logging
authorMelanie Plageman <melanieplageman@gmail.com>
Wed, 12 Mar 2025 15:33:08 +0000 (11:33 -0400)
committerMelanie Plageman <melanieplageman@gmail.com>
Wed, 12 Mar 2025 15:35:27 +0000 (11:35 -0400)
Add log_connections option 'setup_durations' which logs durations of
several key parts of connection establishment and backend setup.

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 backend initialization time.

To make this portable, the timings captured in the postmaster (socket
creation time, fork initiation time) are passed through the
BackendStartupData.

Author: Melanie Plageman <melanieplageman@gmail.com>
Reviewed-by: Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
Reviewed-by: Fujii Masao <masao.fujii@oss.nttdata.com>
Reviewed-by: Daniel Gustafsson <daniel@yesql.se>
Reviewed-by: Jacob Champion <jacob.champion@enterprisedb.com>
Reviewed-by: Jelte Fennema-Nio <postgres@jeltef.nl>
Reviewed-by: Guillaume Lelarge <guillaume.lelarge@dalibo.com>
Discussion: https://postgr.es/m/flat/CAAKRu_b_smAHK0ZjrnL5GRxnAVWujEXQWpLXYzGbmpcZd3nLYw%40mail.gmail.com

12 files changed:
doc/src/sgml/config.sgml
src/backend/postmaster/launch_backend.c
src/backend/postmaster/postmaster.c
src/backend/tcop/backend_startup.c
src/backend/tcop/postgres.c
src/backend/utils/init/postinit.c
src/backend/utils/misc/postgresql.conf.sample
src/include/miscadmin.h
src/include/tcop/backend_startup.h
src/include/utils/timestamp.h
src/test/authentication/t/001_password.pl
src/tools/pgindent/typedefs.list

index 2ce93fbfa36adef512f78b5b030c4b048fef9f64..7ece94474d9efb241166f268f5765598efc6ea61 100644 (file)
@@ -7369,6 +7369,19 @@ local0.*    /var/log/postgresql
            </entry>
           </row>
 
+          <row>
+           <entry><literal>setup_durations</literal></entry>
+           <entry>
+            Logs the time spent establishing the connection and setting up the
+            backend at the time the connection is ready to execute its first
+            query. The log message includes the total setup duration, starting
+            from the postmaster accepting the incoming connection and ending
+            when the connection is ready for query. It also includes the time
+            it took to fork the new backend and the time it took to
+            authenticate the user.
+           </entry>
+          </row>
+
           <row>
            <entry><literal>all</literal></entry>
            <entry>
index 47375e5bfaa12befea91313053ac3063008fd9a1..ecd04655c2a4b0b1bcb081dd512518fde36312b1 100644 (file)
@@ -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 (IsExternalConnectionBackend(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 (IsExternalConnectionBackend(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,18 @@ 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.
+    */
+   fork_end = GetCurrentTimestamp();
+
    /* Setup essential subsystems (to ensure elog() behaves sanely) */
    InitializeGUCOptions();
 
@@ -648,6 +669,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 (IsExternalConnectionBackend(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
index b4f34c57a1b7f52197546d54821a55a3f573a3bc..57155c00e017b26d6b473b52adb7f02674be899b 100644 (file)
@@ -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
index 962b6e6000275794c039bd2adb42a533c9b91efc..27c0b3c2b045bd97c9fc6e8037917175bbf540d5 100644 (file)
@@ -46,6 +46,16 @@ bool     Trace_connection_negotiation = false;
 uint32     log_connections = 0;
 char      *log_connections_string = NULL;
 
+/* Other globals */
+
+/*
+ * ConnectionTiming stores timestamps of various points in connection
+ * establishment and setup.
+ * ready_for_use is initialized to a special value here so we can check if
+ * we've already set it before doing so in PostgresMain().
+ */
+ConnectionTiming conn_timing = {.ready_for_use = TIMESTAMP_MINUS_INFINITY};
+
 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);
@@ -1006,6 +1016,7 @@ validate_log_connections_options(List *elemlist, uint32 *flags)
            {"receipt", LOG_CONNECTION_RECEIPT},
            {"authentication", LOG_CONNECTION_AUTHENTICATION},
            {"authorization", LOG_CONNECTION_AUTHORIZATION},
+           {"setup_durations", LOG_CONNECTION_SETUP_DURATIONS},
            {"all", LOG_CONNECTION_ALL},
        };
 
index 947ffb40421cb0ed31368ed3646a9529963198c4..55ab2da299b9028221adb6f879d4c2a6fc624710 100644 (file)
@@ -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"
@@ -4607,6 +4608,38 @@ 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 and setup.
+            */
+           if (conn_timing.ready_for_use == TIMESTAMP_MINUS_INFINITY &&
+               (log_connections & LOG_CONNECTION_SETUP_DURATIONS) &&
+               IsExternalConnectionBackend(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: setup total=%.3f ms, fork=%.3f ms, authentication=%.3f ms",
+                              (double) total_duration / NS_PER_US,
+                              (double) fork_duration / NS_PER_US,
+                              (double) auth_duration / NS_PER_US));
+           }
+
            ReadyForQuery(whereToSendOutput);
            send_ready_for_query = false;
        }
index 6c207e1776888858864a5d651fbe54c41ad1e456..4b2faf1ba9d2dca9626bbd28a3acd3edf4d9115c 100644 (file)
@@ -235,6 +235,9 @@ PerformAuthentication(Port *port)
    }
 #endif
 
+   /* Capture authentication start time for logging */
+   conn_timing.auth_start = GetCurrentTimestamp();
+
    /*
     * Set up a timeout in case a buggy or malicious client fails to respond
     * during authentication.  Since we're inside a transaction and might do
@@ -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_AUTHORIZATION)
    {
        StringInfoData logmsg;
index c291c05d18145d91e5d2cc9b161d2ed0b2e3db03..d2bd329a587aa1add7286536faa1df6b410db41c 100644 (file)
 #log_checkpoints = on
 #log_connections = '' # log aspects of connection setup
           # options include receipt, authentication, authorization,
-          # and all to log all of these aspects
+          # setup_durations, and all to log all of these aspects
 #log_disconnections = off
 #log_duration = off # log statement duration
 #log_error_verbosity = default     # terse, default, or verbose messages
index a2b63495eecbb30fb23f82b2de8ddbff488e0309..6f16794eb63c6899dd9f7c55c0315b0b5340916a 100644 (file)
@@ -394,6 +394,14 @@ extern PGDLLIMPORT BackendType MyBackendType;
    (AmAutoVacuumLauncherProcess() || \
     AmLogicalSlotSyncWorkerProcess())
 
+/*
+ * Backend types that are spawned by the postmaster to serve a client or
+ * replication connection. These backend types have in common that they are
+ * externally initiated.
+ */
+#define IsExternalConnectionBackend(backend_type) \
+   (backend_type == B_BACKEND || backend_type == B_WAL_SENDER)
+
 extern const char *GetBackendTypeDesc(BackendType backendType);
 
 extern void SetDatabasePath(const char *path);
index e00851a004e4bf4492cbcbaaa5bbfcdc99b3b544..2912ef802889f73dbb75bef941a10ef8b097a780 100644 (file)
 #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,14 +44,27 @@ 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.
  *
- * RECEIPT, AUTHENTICATION, and AUTHORIZATION are different aspects of
- * connection establishment and backend setup for which we may emit a log
- * message.
+ * RECEIPT, AUTHENTICATION, AUTHORIZATION, and SETUP_DURATIONS are different
+ * aspects of connection establishment and backend setup for which we may emit
+ * a log message.
  *
  * ALL is a convenience alias equivalent to all of the above aspects.
  *
@@ -58,6 +76,7 @@ typedef enum LogConnectionOption
    LOG_CONNECTION_RECEIPT = (1 << 0),
    LOG_CONNECTION_AUTHENTICATION = (1 << 1),
    LOG_CONNECTION_AUTHORIZATION = (1 << 2),
+   LOG_CONNECTION_SETUP_DURATIONS = (1 << 3),
    LOG_CONNECTION_ON =
        LOG_CONNECTION_RECEIPT |
        LOG_CONNECTION_AUTHENTICATION |
@@ -65,9 +84,39 @@ typedef enum LogConnectionOption
    LOG_CONNECTION_ALL =
        LOG_CONNECTION_RECEIPT |
        LOG_CONNECTION_AUTHENTICATION |
-       LOG_CONNECTION_AUTHORIZATION,
+       LOG_CONNECTION_AUTHORIZATION |
+       LOG_CONNECTION_SETUP_DURATIONS,
 } LogConnectionOption;
 
+/*
+ * A collection of timings of various stages of connection establishment and
+ * setup for client backends and WAL senders.
+ *
+ * Used to emit the setup_durations log message for 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 */
index 9963bddc0ecefbda2c3f4559e8e2d20455acad07..8c205859c3be5b7598246a32d5e6205b18417074 100644 (file)
@@ -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;
index e307dee5c486ed5c5c0aebef8c0fe84e57dee31a..8269c470b5977cafa0070b178d433547d3be4959 100644 (file)
@@ -77,8 +77,22 @@ $node->start;
 # other tests are added to this file in the future
 $node->safe_psql('postgres', "CREATE DATABASE test_log_connections");
 
+my $log_connections = $node->safe_psql('test_log_connections', q(SHOW log_connections;));
+is($log_connections, 'on', qq(check log connections has expected value 'on'));
+
+$node->connect_ok('test_log_connections',
+   qq(log_connections 'on' works as expected for backwards compatibility),
+   log_like => [
+       qr/connection received/,
+       qr/connection authenticated/,
+       qr/connection authorized: user=\S+ database=test_log_connections/,
+   ],
+   log_unlike => [
+       qr/connection ready/,
+   ],);
+
 $node->safe_psql('test_log_connections',
-   q[ALTER SYSTEM SET log_connections = receipt,authorization;
+   q[ALTER SYSTEM SET log_connections = receipt,authorization,setup_durations;
                   SELECT pg_reload_conf();]);
 
 $node->connect_ok('test_log_connections',
@@ -86,6 +100,7 @@ $node->connect_ok('test_log_connections',
    log_like => [
        qr/connection received/,
        qr/connection authorized: user=\S+ database=test_log_connections/,
+       qr/connection ready/,
    ],
    log_unlike => [
        qr/connection authenticated/,
@@ -100,6 +115,7 @@ $node->connect_ok('test_log_connections',
        qr/connection received/,
        qr/connection authenticated/,
        qr/connection authorized: user=\S+ database=test_log_connections/,
+       qr/connection ready/,
    ],);
 
 # Authentication tests
index 9e7f58adb18ecab64a1a9bf6db23de7481a9ed6d..a2e592dbbbbf24acfd1e2cf2d91e0a6044a73e29 100644 (file)
@@ -484,6 +484,7 @@ ConnParams
 ConnStatusType
 ConnType
 ConnectionStateEnum
+ConnectionTiming
 ConsiderSplitContext
 Const
 ConstrCheck