Re: Log connection establishment timings - Mailing list pgsql-hackers

Hi,

On Wed, Mar 05, 2025 at 06:40:10PM -0500, Melanie Plageman wrote:
> On Wed, Mar 5, 2025 at 10:46 AM Melanie Plageman
> <melanieplageman@gmail.com> wrote:
> >
> > As such, I wonder if my PGC_SET idea is not worth the effort and I
> > should revise the earlier patch version which specified the stages but
> > allow for on, off, true, yes, 1 for backwards compatibility and not
> > include disconnections (so we don't remove the log_disconnections GUC
> > this release).
> 
> Okay! Attached v10 does this.

Great, thanks for it!

> It turns log_connections into a string
> but supports all the common values of the current log_connections
> boolean.
> 
> So, you can specify
>    log_connections = authorized,authenticated

Yeah, when used like psql -d "options=-clog_connections=authorized,authenticated"
but needs to be log_connections = 'authorized,authenticated' in the postgresql.conf
file. That makes fully sense.

> But, this is the first version of the patch where I am happy with the
> interface and with the code. It isn't a breaking change (since on,
> off, true, false, etc still work), so I think it is still okay to
> target 18.

A few comments about 0001:

=== 1

we have this:

+       /* For backwards compatability, we accept these tokens by themselves */
+       static const struct config_enum_entry compat_options[] = {
+               {"off", 0},
+               {"false", 0},
+               {"no", 0},
+               {"0", 0},
+               {"on", LOG_CONNECTION_ON},
+               {"true", LOG_CONNECTION_ON},
+               {"yes", LOG_CONNECTION_ON},
+               {"1", LOG_CONNECTION_ON},
+       };

and

+typedef enum LogConnectionOption
+{
+       LOG_CONNECTION_RECEIVED = (1 << 0),
+       LOG_CONNECTION_AUTHENTICATED = (1 << 1),
+       LOG_CONNECTION_AUTHORIZED = (1 << 2),
+       LOG_CONNECTION_ON =
+               LOG_CONNECTION_RECEIVED |
+               LOG_CONNECTION_AUTHENTICATED |
+               LOG_CONNECTION_AUTHORIZED,
+       LOG_CONNECTION_ALL =
+               LOG_CONNECTION_ON,
+} LogConnectionOption;

what do you think about also doing?

        static const struct config_enum_entry compat_options[] = {
-               {"off", 0},
-               {"false", 0},
-               {"no", 0},
-               {"0", 0},
+               {"off", LOG_CONNECTION_OFF},
+               {"false", LOG_CONNECTION_OFF},
+               {"no", LOG_CONNECTION_OFF},
+               {"0", LOG_CONNECTION_OFF},

and

 typedef enum LogConnectionOption
 {
+       LOG_CONNECTION_OFF = 0,
        LOG_CONNECTION_RECEIVED = (1 << 0),
and

    /* If an empty string was passed, we're done. */
    if (list_length(elemlist) == 0)
        return LOG_CONNECTION_OFF;

=== 2

-       if (Log_connections && status == STATUS_OK &&
+       if (log_connections & LOG_CONNECTION_AUTHENTICATED &&
+               status == STATUS_OK &&

Worth to add extra parentheses around (log_connections & LOG_CONNECTION_AUTHENTICATED)?

Not necessary as bitwise AND has higher precedence than logical AND but I think
it makes the code more readable.

=== 3

+       /* If an empty string was passed, we're done. */
+       if (list_length(elemlist) == 0)
+               return 0;
+
+       /*
+        * Now check for the backwards compatability options. They must always be
+        * specified on their own, so we error out if the first option is a
+        * backwards compatability option and other options are also specified.
+        */
+       item = linitial(elemlist);
+
+       for (size_t i = 0; i < lengthof(compat_options); i++)
+       {
+               struct config_enum_entry option = compat_options[i];
+
+               if (pg_strcasecmp(item, option.name) != 0)
+                       continue;
+
+               if (list_length(elemlist) > 1)
+               {

what about storing the list_length(elemlist) at the start to avoid the multiple
list_length(elemlist) calls?

=== 4

+       /* If an empty string was passed, we're done. */

s/done./done/? (Looking at the one line comments around)

=== 5

+       /* Now check the stage-specific options. */

s/options./options/? (Looking at the one line comments around)

=== 6

+       /* For backwards compatability, we accept these tokens by themselves */

Typo: compatability/compatibility

, seen multiple times:

$ git grep compatability
doc/src/sgml/config.sgml:        For the purposes of backwards compatability, <literal>on</literal>,
src/backend/tcop/backend_startup.c:     /* For backwards compatability, we accept these tokens by themselves */
src/backend/tcop/backend_startup.c:      * Now check for the backwards compatability options. They must always be
src/backend/tcop/backend_startup.c:      * backwards compatability option and other options are also specified.
src/include/tcop/backend_startup.h: * ON is backwards compatability alias for the connection events that were

=== 7

+       /* Time for cleanup and allocating `extra` if we succeeded */
+       pfree(rawstring);
+       list_free(elemlist);
+
+       /* We didn't succeed */
+       if (flags == -1)
+               return false;

I feel the first comment is confusing, maybe the "allocating `extra` if we succeeded"
should be put after the "if (flags == -1)" part?

The logic in 0001 looks good to me, also I did a few tests and that looks ok
seen from here.

> In 0002, because we take the timings for all wal sender and client
> connection backends, now the new log message emitted in 0002 is more
> like a stage, so I've named that option "ready_for_query". As such, I
> wonder if I should change the output message to reflect that. What do
> you think?
> 

hmm, I'm tempted to vote for "timings". I understand your point but "timings"
more directly communicates that this option enables timing measurements,
whereas "ready_for_query" describes just one particular state.

I think I could vote for "ready_for_query" should the GUC be log_connection_stages
(and not log_connections).

I also think that we can keep "reported_first_ready_for_query", "send_ready_for_query"
in the code though (even if the GUC option is changed to "timings").

A few comments about 0002:

==== 8

+       if (IsConnectionBackend(child_type))

IsConnectionBackend is fine by me.

=== 9

+  /* Calculate fork duration since we have start and end times. */

s/times./times/? (Looking at the one line comments around)

=== 10

+  /* Will be used to calculate total connection setup duration. */

s/duration./duration/? (Looking at the one line comments around)

=== 11

+       /* How long it took the backend to be forked. */

s/forked./forked/? (Looking at the one line comments around)

=== 12

+      if (!reported_first_ready_for_query &&
+          log_connections & LOG_CONNECTION_READY_FOR_QUERY &&
+          IsConnectionBackend(MyBackendType))

same as comment === 2 above.

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com