aboutsummaryrefslogtreecommitdiff
diff options
context:
space:
mode:
Diffstat
-rw-r--r--doc/src/sgml/config.sgml13
-rw-r--r--src/backend/postmaster/launch_backend.c31
-rw-r--r--src/backend/postmaster/postmaster.c6
-rw-r--r--src/backend/tcop/backend_startup.c11
-rw-r--r--src/backend/tcop/postgres.c33
-rw-r--r--src/backend/utils/init/postinit.c6
-rw-r--r--src/backend/utils/misc/postgresql.conf.sample2
-rw-r--r--src/include/miscadmin.h8
-rw-r--r--src/include/tcop/backend_startup.h57
-rw-r--r--src/include/utils/timestamp.h9
-rw-r--r--src/test/authentication/t/001_password.pl18
-rw-r--r--src/tools/pgindent/typedefs.list1
12 files changed, 189 insertions, 6 deletions
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 2ce93fbfa36..7ece94474d9 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -7370,6 +7370,19 @@ local0.* /var/log/postgresql
</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>
A convenience alias equivalent to specifying all options. If
diff --git a/src/backend/postmaster/launch_backend.c b/src/backend/postmaster/launch_backend.c
index 47375e5bfaa..ecd04655c2a 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 (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
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
@@ -3478,6 +3478,12 @@ BackendStartup(ClientSocket *client_sock)
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
* slots) cleanly.
diff --git a/src/backend/tcop/backend_startup.c b/src/backend/tcop/backend_startup.c
index 962b6e60002..27c0b3c2b04 100644
--- a/src/backend/tcop/backend_startup.c
+++ b/src/backend/tcop/backend_startup.c
@@ -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},
};
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 947ffb40421..55ab2da299b 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"
@@ -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;
}
diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
index 6c207e17768..4b2faf1ba9d 100644
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -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;
diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index c291c05d181..d2bd329a587 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -580,7 +580,7 @@
#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
diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h
index a2b63495eec..6f16794eb63 100644
--- a/src/include/miscadmin.h
+++ b/src/include/miscadmin.h
@@ -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);
diff --git a/src/include/tcop/backend_startup.h b/src/include/tcop/backend_startup.h
index e00851a004e..2912ef80288 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,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 */
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 e307dee5c48..8269c470b59 100644
--- a/src/test/authentication/t/001_password.pl
+++ b/src/test/authentication/t/001_password.pl
@@ -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
diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list
index 9e7f58adb18..a2e592dbbbb 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
generated by cgit v1.2.3 (git 2.25.1) at 2025-05-20 20:54:19 +0000