Re: Log connection establishment timings

Thanks for the continued review!

Attached v11 has a test added (passes locally but fails in CI, so I
have to fix that).
I still need to do some more manual testing and validation.

On Thu, Mar 6, 2025 at 9:56 AM Bertrand Drouvot
<bertranddrouvot(dot)pg(at)gmail(dot)com> wrote:
>
<-- snip -->
> 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;

Yes, I do notice that most GUCs with enums that have an "off" switch
also have a "NONE" or "OFF" enumeration value. This is to contrast it
with a GUC that doesn't have an "off" switch (like wal_level). So, I
think you're right that we should have something to indicate you can
turn off log_connections.

However, I was a bit torn about LOG_CONNECTION_OFF vs
LOG_CONNECTION_NONE. We have LOG_CONNECTION_ON because it is a
legitimately distinct alias for the log messages emitted by < pg 18
when log_connections == on. However, LOG_CONNECTION_NONE and
LOG_CONNECTION_OFF would be the same. As such, I prefer
LOG_CONNECTION_NONE because it makes more sense in the context of
where the enumeration is defined. I've added this and used it in the
compat_options array. What do you think? Is it too confusing?

> - 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.

Done in all places (I think).

> + /* If an empty string was passed, we're done. */
> + if (list_length(elemlist) == 0)
> + return 0;
> +
< -- snip -->
> what about storing the list_length(elemlist) at the start to avoid the multiple
> list_length(elemlist) calls?

Since it would only be called twice and it has the length stored in
the List struct, I prefer it as is -- without an extra local variable.

> + /* If an empty string was passed, we're done. */
>
> s/done./done/? (Looking at the one line comments around)

I've addressed all of these comment punctuations you've mentioned. Thanks!

> === 6
>
> + /* For backwards compatability, we accept these tokens by themselves */
>
> Typo: compatability/compatibility

Whoops! Thanks. I forgot to spell check my commit message. Done that now too.

How do you find spelling mistakes in patches usually? I tried `git
show | aspell list` -- but of course that includes lots of variables
and such that aren't actually spelling mistakes.

> + /* 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?

Fixed.

> > 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.

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?

I didn't change it in the attached version 11. I wanted to discuss
more before making that decision.

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 think I could vote for "ready_for_query" should the GUC be log_connection_stages
> (and not log_connections).

All the existing connection messages are at certain stages and fall in
this category. However, were we to add more that don't fall in that
category, we'd have to think about how to modularize them. I'm not
sure if we could mix connection stages and other assorted message
types easily without the groupings you've mentioned in the past. What
we don't want to do is make a change that makes that harder to do in
the future.

- Melanie