Re: Log connection establishment timings

Thanks for the review!

On Fri, Mar 7, 2025 at 2:08 AM Fujii Masao <masao(dot)fujii(at)oss(dot)nttdata(dot)com> wrote:
>
> With the patch, any unambiguous prefix of a valid boolean value,
> like 'y', is no longer accepted even though it's currently valid
> for boolean GUCs. I don’t have a strong opinion on whether
> we should maintain compatibility for this, but I wanted to
> mention it for the record. If we do, we might need to use
> parse_bool() to interpret the values.

Indeed. In fact, in master, any substring of true/yes/false/no would
be accepted. So I could set log_connections = tr;
It's true that with this patch only on,off,true,false,1,0,yes,no would
be supported. But I think that is okay. If we allow arbitrary
unambiguous substrings of the previously accepted values, it limits
what future log_connections options we can add (they couldn't clash
with any of those substrings or introduce ambiguity). I think it's
better we just draw a line now.

There is one complication, the boolean GUC infrastructure parses those
inputs but then the output is always "on" or "off" in this case. So,
on master if you set log_connections=1 and then do "show
log_connections" it will display "on". With this patch it would
display 1. We may be able to solve that with a show hook, but my
instinct is that that is not worth it. What do you think?

> + * NONE is an alias for when no connection logging should be done.
>
> The comment about "NONE" should be removed since LOG_CONNECTION_NONE was deleted.

Thanks! Fixed in attached v13.

> +typedef enum LogConnectionOption
> +{
> + LOG_CONNECTION_RECEIVED = (1 << 0),
> + LOG_CONNECTION_AUTHENTICATED = (1 << 1),
>
> Since the GUC is named log_connections, I'm tempted to name
> LOG_CONNECTIONS_XXX and LogConnectionsOption here instead.
> This is just a suggestion. If others prefer the current names,
> I’m fine with that.

For the enum and its values, I prefer the singular. log_connections is
about logging all connections. However, when we use these enums, it is
about logging a particular connection, so the singular feels more
appropriate.

> Comments for v2:
>
> + if (IsConnectionBackend(child_type))
> + conn_timing.fork_end = GetCurrentTimestamp();
>
> In SubPostmasterMain(), GetCurrentTimestamp() is called twice to
> set fork_end. It seems unnecessary. We can remove the above call?

Whoops! Thanks for catching this. Fixed in attached v12.

> + /* Capture authentication start time for logging */
> + conn_timing.auth_start = GetCurrentTimestamp();
>
> In the EXEC_BACKEND case, the authentication start time differs
> from when the authentication timeout begins. But shouldn't these
> be the same?

Good point. At some point, I thought maybe it made sense to include
the EXEC_BACKEND-specific setup stuff in the authentication duration
since it is one of the overheads of doing authentication on an
EXEC_BACKEND backend. But, now I realize you are right -- the user
wants to know, if, for example, something weird is happening in a
library somewhere that is making authentication really slow -- not how
long it took to reload the HBA file. I've changed it as you suggested.

An unrelated note about the attached v13:
I changed the language from log_connections "stages" to "options" and
"aspects" depending on the context. I also changed the name of the
option introduced in 0002 to "durations".

I'm a bit torn about having the tests in authentication/001_password.
On the one hand, it doesn't make sense to make a separate test file
and initialize a new postgres just to test two or three options of one
GUC. On the other hand, these tests don't fit very well in any
existing test file I could find. Maybe it is fine that they are in a
file about testing password authentication...

- Melanie