[CF 5442] v14 - Log connection establishment timings

This branch was automatically generated by a robot using patches from an
email thread registered at:

https://commitfest.postgresql.org/patch/5442

The branch will be overwritten each time a new patch version is posted to
the thread, and also periodically to check for bitrot caused by changes
on the master branch.

Patch(es): https://www.postgresql.org/message-id/CAAKRu_Zgk-_xLxpddscwYSzGXS_jbLS_fzK1TvjUBYFDEXuPMg@mail.gmail.com
Author(s): Melanie Plageman

Author: Commitfest Bot

doc/src/sgml/config.sgml

@@ -7315,20 +7315,100 @@ local0.*    /var/log/postgresql
      </varlistentry>
 
      <varlistentry id="guc-log-connections" xreflabel="log_connections">
-      <term><varname>log_connections</varname> (<type>boolean</type>)
+      <term><varname>log_connections</varname> (<type>string</type>)
       <indexterm>
        <primary><varname>log_connections</varname> configuration parameter</primary>
       </indexterm>
       </term>
       <listitem>
        <para>
-        Causes each attempted connection to the server to be logged,
-        as well as successful completion of both client authentication (if
-        necessary) and authorization.
+        Causes aspects of each connection attempt to the server to be
+        logged. The default is the empty string, <literal>''</literal>,
+        which disables all connection logging. The following options may
+        be specified alone or in a comma-separated list:
+       </para>
+
+       <table id="log-connections-options">
+        <title>Log Connection Options</title>
+        <tgroup cols="2">
+         <colspec colname="col1" colwidth="1*"/>
+         <colspec colname="col2" colwidth="2*"/>
+         <thead>
+          <row>
+           <entry>Name</entry>
+           <entry>Description</entry>
+          </row>
+         </thead>
+         <tbody>
+          <row>
+           <entry><literal>receipt</literal></entry>
+           <entry>Logs receipt of a connection.</entry>
+          </row>
+
+          <row>
+           <entry><literal>authentication</literal></entry>
+           <entry>
+            Logs the original identity used by an authentication method
+            to identify a user. In most cases, the identity string
+            matches the PostgreSQL username, but some third-party
+            authentication methods may alter the original user
+            identifier before the server stores it. Failed
+            authentication is always logged regardless of the value of
+            this setting.
+           </entry>
+          </row>
+
+          <row>
+           <entry><literal>authorization</literal></entry>
+           <entry>
+            Logs successful completion of authorization. At this point
+            the connection has been established but the backend is not
+            yet fully set up. The log message includes the authorized
+            username as well as the database name and application name,
+            if applicable.
+           </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>
+            A convenience alias equivalent to specifying all options. If
+            <literal>all</literal> is specified in a list of other
+            options, all connection aspects will be logged.
+           </entry>
+          </row>
+
+         </tbody>
+        </tgroup>
+       </table>
+
+       <para>
+        For the purposes of backwards compatibility, <literal>on</literal>,
+        <literal>off</literal>, <literal>true</literal>,
+        <literal>false</literal>, <literal>yes</literal>,
+        <literal>no</literal>, <literal>1</literal>, and <literal>0</literal>
+        are still supported. The positive values are equivalent to specifying
+        the <literal>receipt</literal>, <literal>authentication</literal>, and
+        <literal>authorization</literal> options.
+       </para>
+
+       <para>
         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.
-        The default is <literal>off</literal>.
        </para>
 
        <note>

src/backend/libpq/auth.c

@@ -38,6 +38,7 @@
 #include "postmaster/postmaster.h"
 #include "replication/walsender.h"
 #include "storage/ipc.h"
+#include "tcop/backend_startup.h"
 #include "utils/memutils.h"
 
 /*----------------------------------------------------------------
@@ -317,7 +318,8 @@ auth_failed(Port *port, int status, const char *logdetail)
 /*
  * Sets the authenticated identity for the current user.  The provided string
  * will be stored into MyClientConnectionInfo, alongside the current HBA
- * method in use.  The ID will be logged if log_connections is enabled.
+ * method in use.  The ID will be logged if log_connections has the
+ * 'authentication' option specified.
  *
  * Auth methods should call this routine exactly once, as soon as the user is
  * successfully authenticated, even if they have reasons to know that
@@ -349,7 +351,7 @@ set_authn_id(Port *port, const char *id)
 	MyClientConnectionInfo.authn_id = MemoryContextStrdup(TopMemoryContext, id);
 	MyClientConnectionInfo.auth_method = port->hba->auth_method;
 
-	if (Log_connections)
+	if (log_connections & LOG_CONNECTION_AUTHENTICATION)
 	{
 		ereport(LOG,
 				errmsg("connection authenticated: identity=\"%s\" method=%s "
@@ -633,7 +635,8 @@ ClientAuthentication(Port *port)
 #endif
 	}
 
-	if (Log_connections && status == STATUS_OK &&
+	if ((log_connections & LOG_CONNECTION_AUTHENTICATION) &&
+		status == STATUS_OK &&
 		!MyClientConnectionInfo.authn_id)
 	{
 		/*

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 (IsConnectionBackend(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 (IsConnectionBackend(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 (IsConnectionBackend(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

src/backend/postmaster/postmaster.c

@@ -237,7 +237,6 @@ int			PreAuthDelay = 0;
 int			AuthenticationTimeout = 60;
 
 bool		log_hostname;		/* for ps display and logging */
-bool		Log_connections = false;
 
 bool		enable_bonjour = false;
 char	   *bonjour_name;
@@ -3478,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