Re: Log connection establishment timings

On Mon, Mar 10, 2025 at 5:03 PM Daniel Gustafsson <daniel(at)yesql(dot)se> wrote:
>
> > On 7 Mar 2025, at 23:08, Melanie Plageman <melanieplageman(at)gmail(dot)com> wrote:
>
> Sorry for being late to the party. I like this functionality and would
> definitely like to see it in v18.

Thanks so much for the review!

> + /* For backwards compatibility, 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},
> + };
> It's not documented here that the backwards compatibility will turn the
> LOG_CONNECTION_ON value into a set of the new fine-grained value. A brief
> mention would be good for future code reading (or a hint to look for details in
> src/include/tcop/backend_startup.h).

I've added a comment about this in attached v14.

> + LOG_CONNECTION_ON =
> + LOG_CONNECTION_RECEIPT |
> + LOG_CONNECTION_AUTHENTICATION |
> + LOG_CONNECTION_AUTHORIZATION,
> + LOG_CONNECTION_ALL =
> + LOG_CONNECTION_ON,
> Nitpick I know, but reusing the backwards compatible _ON for _ALL makes it seem
> like they are the other way around (_ALL being for backwards compat). 0002
> makes it less so but I would prefer to spend the extra lines of code and spell
> out both.

Done.

> +#define IsConnectionBackend(backend_type) \
> This feels like a slightly too generic name to fully convey what it does. I
> don't have a better one off the cuff but I had to refer back multiple times to
> remind myself what it did.

Is `IsClientBackend()` better? It doesn't sound immediately like it
includes WAL sender backends (replication connections), but those are
initiated by clients too, right?

I didn't change it in v14 because I wasn't sure it was better and
wanted to hear what you thought.

> + backend at the time the connection is ready for use. The log
> I'm not sure if "ready for use" will be clear for all readers? The other
> options are using a bit more precise language.

I've tried to clear this up.

> + {"durations", LOG_CONNECTION_DURATIONS},
> I think "durations" is a good name for this, but we risk causing some confusion
> in postgresql.conf when set, as it will end up like this:
>
> log_connections = durations
> #log_disconnections = off
> #log_duration = off
>
> How log_connections=durations and log_duration=off are related might not be
> immediately obvious to new users. Can we avoid confusion by adding comments on
> these log entries perhaps?

I forgot about log_duration and that log_disconnections prints the
connection duration. Thinking about it more and taking into account
something Bertrand suggested upthread, I decided to rename the option
"setup_durations". It's a bit long, but it does convey that these
durations are only about connection setup.

I also added more details about what this is both to docs and
postgresql.conf.sample. Thanks!

> + errmsg("connection ready: total=%.3f ms, fork=%.3f ms, authentication=%.3f ms",
> The use of "total" here makes it seem like (fork+authentication)=total. Not
> sure if we can do better and still be descriptive. Maybe it's a case of
> documenting it if there are questions or complaints?

I've changed it to "setup total=xxx ms, fork=xxx...". I also added
details about the component durations to the docs.

> > I'm a bit torn about having the tests in authentication/001_password.
>
> Agreed, they're not a great fit and it's not where I would look for them. That
> being said, paying for spinning up a new cluster for just this also doesn't
> seem great. Maybe adding a comment in the test file explaining why they are in
> there could help readers.

Yep, added the comment.

I did more manual testing of my patches, and I think they are mostly
ready for commit except for the IsConnectionBackend() macro (if we
have something to change it to).

I did notice one other thing, though. Because
process_startup_options() is called after all the existing
log_connections messages are emitted, setup_durations behaves a bit
differently than the other options. I actually think the other
log_connections options are not quite right, so perhaps it is okay
that the new option is different if it is more compliant.

For example, if you start from a freshly initdb'd cluster and do ALTER
SYSTEM SET log_connections='all', then restart or reload the conf file
and reconnect, you'll see the receipt, authentication, authorization,
and setup_durations messages. If you then `export PGOPTIONS="-c
log_connections="` and reconnect again, you'll see the receipt,
authentication, and authorization messages but not the setup_durations
message. The setup_durations message is emitted after we process
PGOPTIONS and set log_connections = ''. I think this behavior is okay,
though I'm not sure if/where it should be documented

- Melanie