</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>
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);
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);
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();
/* 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
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
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);
{"receipt", LOG_CONNECTION_RECEIPT},
{"authentication", LOG_CONNECTION_AUTHENTICATION},
{"authorization", LOG_CONNECTION_AUTHORIZATION},
+ {"setup_durations", LOG_CONNECTION_SETUP_DURATIONS},
{"all", LOG_CONNECTION_ALL},
};
#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"
/* 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;
}
}
#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
*/
disable_timeout(STATEMENT_TIMEOUT, false);
+ /* Capture authentication end time for logging */
+ conn_timing.auth_end = GetCurrentTimestamp();
+
if (log_connections & LOG_CONNECTION_AUTHORIZATION)
{
StringInfoData logmsg;
#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
(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);
#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
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.
*
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 |
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 */
#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;
# 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',
log_like => [
qr/connection received/,
qr/connection authorized: user=\S+ database=test_log_connections/,
+ qr/connection ready/,
],
log_unlike => [
qr/connection authenticated/,
qr/connection received/,
qr/connection authenticated/,
qr/connection authorized: user=\S+ database=test_log_connections/,
+ qr/connection ready/,
],);
# Authentication tests
ConnStatusType
ConnType
ConnectionStateEnum
+ConnectionTiming
ConsiderSplitContext
Const
ConstrCheck
projects / postgresql.git / commitdiff