Re: Log connection establishment timings

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(at)gmail(dot)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