Re: Log connection establishment timings

Attached v9 implements log_connections as an enum with a new third
value "timings".

On Mon, Mar 3, 2025 at 11:14 AM Bertrand Drouvot
<bertranddrouvot(dot)pg(at)gmail(dot)com> wrote:
>
>
> On Fri, Feb 28, 2025 at 05:52:35PM -0500, Melanie Plageman wrote:
>
> > We have to be really careful about when log_connections is actually
> > set before we use it -- I fixed some issues with that.
>
> Good catch! Yeah for the EXEC_BACKEND case we need to wait that read_nondefault_variables()
> in SubPostmasterMain() is executed.

Due to this and the bug Fujii-san reported with passing options to
psql (process_startup_options() is called too late for us to use the
value of log_connections as a gate for getting any of the timings),
I've decided to get the time regardless of the setting of
log_connections. This means we can be sure to have valid values at the
end when the message needs to be emitted.

I was wondering if we should remove the backend type condition
(B_WAL_SENDER/B_BACKEND) too. It is only guarding capturing the fork
start and end time. That's just two measurements. Maybe we should just
always get fork start and end time. Spending extra time in forking due
to excess CPU activity (or some other reason) would be relevant for
all backend types, not just wal sender and client backends. We do only
want to log it in those cases, though...

> +bool
> +check_log_connections(char **newval, void **extra, GucSource source)
> +{
>
> This function is pretty close to check_debug_io_direct() for example and its
> overall content, memory management, looks good to me. I just have a few
> following comments about it.

Yep, one more reason I think PGC_SET is a good idea. Code deduplication.

> +typedef enum ConnectionLogOption
> +{
> + LOG_CONNECTION_RECEIVED = (1 << 0),
> + LOG_CONNECTION_AUTHENTICATED = (1 << 1),
> + LOG_CONNECTION_AUTHORIZED = (1 << 2),
> + LOG_CONNECTION_DISCONNECTED = (1 << 3),
> +} ConnectionLogOption;
>
> I wonder if it would make sense to add LOG_CONNECTION_ALL here
> (LOG_CONNECTION_RECEIVED | LOG_CONNECTION_AUTHENTICATED ..)
>
> That sounds a better place (than defining "all" in check_log_connections()) to
> me. It's also how it is done in MonotonicFunction.

The attached patch doesn't work exactly the same because it is a
regular enum and not a string list (so no "all"), but I do still have
a LogConnectionOption. The user interface is that timings includes all
the same messages as "on", however for the enum, I've defined it like
this:

typedef enum LogConnectionOption
{
LOG_CONNECTION_BASIC = (1 << 0),
LOG_CONNECTION_TIMINGS = (1 << 1),
} LogConnectionOption;

and then in the enum array, I have this

static const struct config_enum_entry log_connections_options[] = {
{"timings", LOG_CONNECTION_TIMINGS | LOG_CONNECTION_BASIC, false},

This is in contrast to MonotonicFunction which defines
MONOTONICFUNC_BOTH as including both values in the enum

typedef enum MonotonicFunction
{
MONOTONICFUNC_NONE = 0,
MONOTONICFUNC_INCREASING = (1 << 0),
MONOTONICFUNC_DECREASING = (1 << 1),
MONOTONICFUNC_BOTH = MONOTONICFUNC_INCREASING | MONOTONICFUNC_DECREASING,
} MonotonicFunction;

I think the way I've done it makes sense because the "business logic"
of how "timings" includes all the messages from "on" doesn't have to
pollute the code and doesn't take away our ability to use the enum
values independently.

When I want to emit a regular logging message, I can just check
if (log_connections & LOG_CONNECTION_BASIC)
which will work for "timings" too, but without taking away the
flexibility to use the enum values discretely.

> Also not sure if it's worth adding a "MAX" (like it's done for relopt_kind)
> because we'd probably not go over it anyay.
>
> "
> /* some compilers treat enums as signed ints, so we can't use 1 << 31 */
> RELOPT_KIND_MAX = (1 << 30)

That actually seems kind of broken -- what if it is on a platform
where integers are 16 bits? Maybe we don't support any of those.
Honestly I find the MAX more confusing than not having it at all. I
think we have to assume that programmers know or can look up how many
bits they can use of an enum in C. Or we can just upgrade to c23 and
have explicit underlying types for enums! :)

> s/ConnectionLogOption/LogConnectionOption/? (as it is linked to "log_connections")

Yep. Good idea. I've changed this.

> All the TAP tests have been modified that way:
>
> -$node->append_conf('postgresql.conf', "log_connections = on");
> +$node->append_conf('postgresql.conf', "log_connections = 'all'");
>
> Is it worh to add some checks for the other values?

Now we are back to only having 3 values, but I was thinking if we
wanted to add some test exercising "timings". We can't test any
specific values of any of the durations emitted, so it would have to
just be a test that that log message was emitted. I don't see a very
good place to add such a test though. There is
src/test/postmaster/t/002_connection_limits.pl -- which has to do with
testing different connection limits (like max_connections). I don't
see any other TAP tests that are testing connections. There are a
whole bunch of auth tests, I suppose.

> I did a few manual checks and that seems to work as expected.

Thanks so much for your continued feedback and review!

- Melanie