Re: Log connection establishment timings

On Fri, Mar 7, 2025 at 6:16 AM Bertrand Drouvot
<bertranddrouvot(dot)pg(at)gmail(dot)com> wrote:
>
> On Thu, Mar 06, 2025 at 11:41:03AM -0500, Melanie Plageman wrote:
>
> > Well, I actually didn't want to call it "timings" because it implies
> > that we only measure the timings when it is specified. But we actually
> > get the timings unconditionally for client backends and wal sender.
>
> > Don't you think it is more confusing for the user if we call it
> > timings and users think if they don't include that timings aren't
> > measured?
>
> That's a good question. I think the expectations are set in the log_connections
> GUC documentation. It says "Causes the specified stages of each connection attempt
> to the server to be logged". So for me that would be like: log yes or no the
> timings.
>
> Of course to be logged those need to be measured and one could expect the timings
> not to be measured if timings is not set.
>
> But at the end, what we're "really" interested in this thread, given its $SUBJECT,
> is to actually log the timings.

I thought about this more. Thanks for taking the time to discuss.
For one, I take your point: I originally proposed the patch because we
wanted some visibility into how long various stages of connection
setup took -- not because we wanted to log when the backend was ready
for query. I'm not sure that people would enable this option much if
it was called ready_for_use, since just logging when we are ready for
query is likely not that valuable.

This got me thinking more about the existing log connections messages
and whether or not they are actually all "stages". The authenticated
and authorized messages occur at nearly the same time in the
connection establishment timeline. So it seems like they aren't really
distinct stages. The messages contain different information and serve
different purposes. Looking at 9afffcb833d, which added the
authentication message, it gives the example of a database user with a
different authentication identity. The authentication message has the
auth id and the auth method. The authorized message has the db and db
username.

So, I would call "received" and "authorized" stages and the
authentication ID message not a stage. I think I should not call these
"log_connections stages" in the docs and comments and instead call
them "log_connections options". That also makes me wonder if the
"authenticated" log_connections option should actually be called
"auth_id" or something similar.

And I am wondering if the "timings" option should be called "timings"
or "durations"? I want to convey that it is about printing connection
setup durations and not about whether or not we measure timings. But
log_connections=durations sounds more like it logs the total duration
of the connection setup and not component parts...

<-- snip-->

> > Also, I thought changing the message output to say "ready for query"
> > somewhere in it makes it more clear when that message is actually
> > emitted in a connection's lifetime. What do you think?
>
> I agree if we keep ready_for_query as the option name.

I actually think even if we change the option name, it could be
valuable to have the message begin with "connection ready for use";
otherwise, it's unclear when we are printing the message. Logging
messages are very tied to what was happening when they were emitted.
Usually they include some context on when they were emitted. Thus, I
think it makes sense to somehow contextualize the message in this way
in the text. It does make the message rather long, though...

- Melanie