Add connection establishment duration logging

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

3 files changed, 70 insertions, 4 deletions

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;