Re: Log connection establishment timings

Hi,

On Tue, Mar 04, 2025 at 06:25:42PM -0500, Melanie Plageman wrote:
> 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 think that makes sense given what has been said in [1].

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

Yeah, I'm on the fence for this one. OTOH that sounds strange to "collect"
data that won't be used for some backend types. So I'm tempted to vote to
keep it as it is.

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

+1

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

Thanks for the new patch!

> doesn't work exactly the same because it is a
> regular enum and not a string list (so no "all")

Yeah, does not make sense anymore.

>, 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},

works for me.

Looking at the enum array:

"
static const struct config_enum_entry log_connections_options[] = {
{"off", 0, false},
{"on", LOG_CONNECTION_BASIC, false},
{"true", LOG_CONNECTION_BASIC, true},
{"false", 0, true},
{"yes", LOG_CONNECTION_BASIC, true},
{"no", 0, true},
{"timings", LOG_CONNECTION_TIMINGS | LOG_CONNECTION_BASIC, false},
{"1", LOG_CONNECTION_BASIC, true},
{"0", 0, true},
{NULL, 0, false}
};
"
and at parse_bool_with_len(), then it looks like it used to work with
log_connections set to things like "y, ye, yes, t, tr, tru, true, f, fa, fal,
fals, false, n and no" but now we want the full words.

I wonder if we should go so deep in the backward compatibility though. Maybe
that's worth to do if simple enough? (not sure how complicated it would be).

The case-insensitive is preserved, I mean "trUe" still works with the patch.

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

Yeah, I like the way it's done.

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

yup.

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

Yeah, good point. Looks like a check on INT_MAX or such is missing. That's
probably worth another thread. I'll do that.

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

yeah...

=== 1

+ ereport(LOG,
+ errmsg("connection establishment times (ms): total: %ld, fork: %ld, authentication: %ld",
+ (long int) INSTR_TIME_GET_MILLISEC(total_duration),
+ (long int) INSTR_TIME_GET_MILLISEC(conn_timing.fork_duration),
+ (long int) INSTR_TIME_GET_MILLISEC(conn_timing.auth_duration)));

I wonder if doing:

+ errmsg("connection establishment times (ms): total: %.3f, fork: %.3f, authentication: %.3f",
+ (double) INSTR_TIME_GET_NANOSEC(total_duration) / 1000000.0,
+ (double) INSTR_TIME_GET_NANOSEC(conn_timing.fork_duration) / 1000000.0,
+ (double) INSTR_TIME_GET_NANOSEC(conn_timing.auth_duration) / 1000000.0));

wouln't be better. For example, on my machine I'd get:

connection establishment times (ms): total: 13.537, fork: 0.619, authentication: 0.267

instead of:

connection establishment times (ms): total: 13, fork: 0, authentication: 0

[1]: https://www.postgresql.org/message-id/bgn52vsoxoqato3l3wqsc3vqyd6xbkvd6ylhmh2yd5m4srjn3n%40j5kocng6bfa2

Regards,

--
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com