Thread: Re: Log connection establishment timings

Re: Log connection establishment timings

From

Guillaume Lelarge

Date:

07 January, 00:08:36

Hello,

Le lun. 16 déc. 2024 à 22:00, Melanie Plageman <melanieplageman@gmail.com> a écrit :

Hi,

Users wishing to debug slow connection establishment have little
visibility into which steps take the most time. We don't expose any
stats and none of the logging includes durations.

The attached patch logs durations for authentication, forking the
Postgres backend, and the end-to-end connection establishment duration
starting from when the postmaster calls accept() and ending the first
time the forked backend is ready for query.

As an example of how this could be useful, I artificially slowed down
authentication and you can see that that is now visible in logs:

LOG: backend ready for query. pid=86341. socket=10. connection
establishment times (ms): total: 8, fork: 0, authentication: 0
LOG: backend ready for query. pid=86794. socket=10. connection
establishment times (ms): total: 108, fork: 0, authentication: 100

Two notes on implementation:

To make this portable, the timestamps captured in the postmaster
(socket creation time, fork initiation time) are passed through the
ClientSocket and BackendStartupData structures instead of simply saved
in backend local memory inherited by the child process.

Secondly, I used TimestampTz for the times, but it is pretty unclear
to me when instr_time should be used vs TimestampTz for such things.
instr_time says it is more portable, but there are all sorts of places
that use TimestampTz that would probably need to be portable.
Also, INSTR_TIME_SUBTRACT() isn't overflow safe, which must be because
the actual data type of ticks is platform dependent and so the caller
is responsible for not passing it values that would overflow when
subtracted.

Just a quick note. I like this patch a lot and it would help to diagnose some situations our customers may have. I tried the patch on my laptop, and it works fine. I'll find some time to read the code as well, but in the meantime, this looks like a nice thing to have in PostgreSQL.

Thanks Melanie.

Guillaume.

Re: Log connection establishment timings

From

Melanie Plageman

Date:

25 February, 23:23:31

Thanks for taking a look!

On Mon, Jan 20, 2025 at 10:01 AM Bertrand Drouvot
<bertranddrouvot.pg@gmail.com> wrote:
>
> The patch needed a rebase due to 34486b6092e. I did it in v2 attached (it's
> a minor rebase due to the AmRegularBackendProcess() introduction in miscadmin.h).
>
> v2 could rely on AmRegularBackendProcess() instead of AmClientBackendProcess()
> but I kept it with AmClientBackendProcess() to reduce "my" changes as compared to
> v1.

Thanks for doing this! I have implemented your suggestion in attached v3.

> Regarding the TimestampTz vs instr_time choice, we have things like:
< -- snip -- >
> So with TimestampTz, we would:
>
> 1. return 0 if we moved the time backward
> 2. provide an inflated duration including the time jump (if the time move
> forward).
>
> But with instr_time (and on systems that support CLOCK_MONOTONIC) then
> pg_clock_gettime_ns() should not be affected by system time change IIUC.
>
> Though time changes are "rare", given the fact that those metrics could provide
> "inaccurate" measurements during that particular moment (time change) then it
> might be worth considering instr_time instead for this particular metric.

Great point. This all makes sense. I've switched to using instr_time in v3.

- Melanie

Attachment

v3-0001-Add-connection-establishment-duration-logging.patch

Re: Log connection establishment timings

From

Melanie Plageman

Date:

25 February, 23:28:28

Thanks for taking a look!

On Mon, Jan 20, 2025 at 12:53 PM Jacob Champion
<jacob.champion@enterprisedb.com> wrote:
>
> On Mon, Jan 20, 2025 at 7:01 AM Bertrand Drouvot
> <bertranddrouvot.pg@gmail.com> wrote:
> > Though time changes are "rare", given the fact that those metrics could provide
> > "inaccurate" measurements during that particular moment (time change) then it
> > might be worth considering instr_time instead for this particular metric.
>
> +1, I think a CLOCK_MONOTONIC source should be used for this if we've got it.

Done in v3 (see [1]).

> For the EXEC_BACKEND case (which, to be honest, I don't know much
> about), I originally wondered if the fork_duration should include any
> of the shared memory manipulations or library reloads that are done to
> match Unix behavior. But I think I prefer the way the patch does it.

You mean if the EXEC_BACKEND not defined version should calculate the
end of fork_duration basically at the end of
postmaster_child_launch()?

> Can the current timestamp be recorded right at the beginning of
> SubPostmasterMain(), to avoid counting the time setting up GUCs and
> reading the variables file, or do we have to wait?

We actually don't have the startup data until after we
read_backend_variables(), so I did it as soon as I could after that.

You are right that this will include timing from some extra steps.
But, some of these steps are overhead unique to the slow process of
"forking" a backend when EXEC_BACKEND is defined anyway, so it
probably makes sense for them to be included in the timing of "fork"
for these backends.

> nit: conn_timing is currently declared in the "interrupts and crit
> section" part of miscadmin.h; should it be moved down to the
> general-purpose globals?

Whoops, it would help if I read comments and stuff. Thanks! Fixed in v3 in [1].

- Melanie

[1] https://www.postgresql.org/message-id/CAAKRu_YrNsA7-v5L9d318XZu%2BtPqcxp%2BctCGy2EGYrSt69ON%3DA%40mail.gmail.com

Re: Log connection establishment timings

From

Melanie Plageman

Date:

26 February, 00:36:44

On Tue, Feb 25, 2025 at 3:23 PM Melanie Plageman
<melanieplageman@gmail.com> wrote:
>
> Thanks for doing this! I have implemented your suggestion in attached v3.

I missed an include in the EXEC_BACKEND not defined case. attached v4
is fixed up.

- Melanie

Attachment

v4-0001-Add-connection-establishment-duration-logging.patch

Re: Log connection establishment timings

From

Fujii Masao

Date:

26 February, 07:46:19

On 2025/02/26 6:36, Melanie Plageman wrote:
> On Tue, Feb 25, 2025 at 3:23 PM Melanie Plageman
> <melanieplageman@gmail.com> wrote:
>>
>> Thanks for doing this! I have implemented your suggestion in attached v3.
> 
> I missed an include in the EXEC_BACKEND not defined case. attached v4
> is fixed up.

Thanks for updating the patch!

+    /* Capture time Postmaster initiates fork for logging */
+    if (child_type == B_BACKEND)
+        INSTR_TIME_SET_CURRENT(((BackendStartupData *) startup_data)->fork_time);

When log_connections is enabled, walsender connections are also logged.
However, with the patch, it seems the connection time for walsenders isn't captured.
Is this intentional?

With the current patch, when log_connections is enabled, the connection time is always
captured, and which might introduce performance overhead. No? Some users who enable
log_connections may not want this extra detail and want to avoid such overhead.
So, would it make sense to extend log_connections with a new option like "timing" and
log the connection time only when "timing" is specified?

+                ereport(LOG,
+                        errmsg("backend ready for query. pid=%d. socket=%d. connection establishment times (ms):
total:%ld, fork: %ld, authentication: %ld",

+                               MyProcPid,
+                               (int) MyClientSocket->sock,

Why expose the socket's file descriptor? I'm not sure how users would use that information.

Including the PID seems unnecessary since it's already available via log_line_prefix with %p?

Regards,

-- 
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION

Re: Log connection establishment timings

From

Bertrand Drouvot

Date:

26 February, 10:41:57

Hi,

On Wed, Feb 26, 2025 at 01:46:19PM +0900, Fujii Masao wrote:
> 
> 
> On 2025/02/26 6:36, Melanie Plageman wrote:
> > On Tue, Feb 25, 2025 at 3:23 PM Melanie Plageman
> > <melanieplageman@gmail.com> wrote:
> > > 
> > > Thanks for doing this! I have implemented your suggestion in attached v3.

Thanks for the new patch version!

> +    /* Capture time Postmaster initiates fork for logging */
> +    if (child_type == B_BACKEND)
> +        INSTR_TIME_SET_CURRENT(((BackendStartupData *) startup_data)->fork_time);
> 
> When log_connections is enabled, walsender connections are also logged.
> However, with the patch, it seems the connection time for walsenders isn't captured.
> Is this intentional?

Good point. I'm tempted to say that it should also be, specially because a
connection done as "psql replication=database" is of "walsender" backend type and
would not be reported.

> With the current patch, when log_connections is enabled, the connection time is always
> captured, and which might introduce performance overhead. No? Some users who enable
> log_connections may not want this extra detail and want to avoid such overhead.
> So, would it make sense to extend log_connections with a new option like "timing" and
> log the connection time only when "timing" is specified?

+1, I also think it's a good idea to let users decide if they want the timing
measurement overhead (and it's common practice with track_io_timing,
track_wal_io_timing, the newly track_cost_delay_timing for example)

> +                ereport(LOG,
> +                        errmsg("backend ready for query. pid=%d. socket=%d. connection establishment times (ms):
total:%ld, fork: %ld, authentication: %ld",
 
> +                               MyProcPid,
> +                               (int) MyClientSocket->sock,
> 
> Why expose the socket's file descriptor? I'm not sure how users would use that information.
> 
> 
> Including the PID seems unnecessary since it's already available via log_line_prefix with %p?

Yeah, we would get things like:

[1111539] LOG:  connection received: host=[local]
[1111539] LOG:  connection authenticated: user="postgres" method=trust
(/home/postgres/postgresql/pg_installed/pg18/data/pg_hba.conf:117)
[1111539] LOG:  connection authorized: user=postgres database=postgres application_name=psql
[1111539] LOG:  backend ready for query. pid=1111539. socket=9. connection establishment times (ms): total: 2, fork: 0,
authentication:0
 

I also wonder if "backend ready for query" is worth it. Maybe something like:

2025-02-26 06:44:23.265 UTC [1111539] LOG:  connection establishment times (ms): total: 2, fork: 0, authentication: 0

would be good enough?

A few random comments:

=== 1

+typedef struct ConnectionTiming
+{
+       instr_time      fork_duration;
+       instr_time      auth_duration;
+} ConnectionTiming;

As it's all about instr_time, I wonder if we could use an enum + array instead.
That's probably just a matter of taste but that sounds more flexible to extend
(should we want to add more timing in the future).

=== 2

+ConnectionTiming conn_timing = {0};

There is no padding in ConnectionTiming and anyway we just access its fields
so that's ok to initialize that way.

=== 3

Add a few words in the log_connections GUC doc? (anyway we will have to if
Fujii-san idea above about the timing is implemented)

=== 4

+               /* Calculate total fork duration in child backend for logging */
+               if (child_type == B_BACKEND)
+               {
+                       INSTR_TIME_SET_CURRENT(conn_timing.fork_duration);
+                       INSTR_TIME_SUBTRACT(conn_timing.fork_duration,
+                                                               ((BackendStartupData *) startup_data)->fork_time);
+               }
+
                /* Close the postmaster's sockets */
                ClosePostmasterPorts(child_type == B_LOGGER);

@@ -618,6 +630,14 @@ SubPostmasterMain(int argc, char *argv[])
        /* Read in the variables file */
        read_backend_variables(argv[2], &startup_data, &startup_data_len);

+       /* Calculate total fork duration in child backend for logging */
+       if (child_type == B_BACKEND)
+       {
+               INSTR_TIME_SET_CURRENT(conn_timing.fork_duration);
+               INSTR_TIME_SUBTRACT(conn_timing.fork_duration,
+                               ((BackendStartupData *) startup_data)->fork_time);
+       }

worth to add a helper function to avoid code duplication?

Regards,

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

Re: Log connection establishment timings

From

Guillaume Lelarge

Date:

26 February, 16:22:32

On 26/02/2025 08:41, Bertrand Drouvot wrote:
> Hi,
> 
> On Wed, Feb 26, 2025 at 01:46:19PM +0900, Fujii Masao wrote:
>>
>>
>> On 2025/02/26 6:36, Melanie Plageman wrote:
>>> On Tue, Feb 25, 2025 at 3:23 PM Melanie Plageman
>>> <melanieplageman@gmail.com> wrote:
>>>>
>>>> Thanks for doing this! I have implemented your suggestion in attached v3.
> 
> Thanks for the new patch version!
> 

+1

>> +    /* Capture time Postmaster initiates fork for logging */
>> +    if (child_type == B_BACKEND)
>> +        INSTR_TIME_SET_CURRENT(((BackendStartupData *) startup_data)->fork_time);
>>
>> When log_connections is enabled, walsender connections are also logged.
>> However, with the patch, it seems the connection time for walsenders isn't captured.
>> Is this intentional?
> 
> Good point. I'm tempted to say that it should also be, specially because a
> connection done as "psql replication=database" is of "walsender" backend type and
> would not be reported.
> 

Agreed.

>> With the current patch, when log_connections is enabled, the connection time is always
>> captured, and which might introduce performance overhead. No? Some users who enable
>> log_connections may not want this extra detail and want to avoid such overhead.
>> So, would it make sense to extend log_connections with a new option like "timing" and
>> log the connection time only when "timing" is specified?
> 
> +1, I also think it's a good idea to let users decide if they want the timing
> measurement overhead (and it's common practice with track_io_timing,
> track_wal_io_timing, the newly track_cost_delay_timing for example)
> 

track_connection_delay_timing ? I'm fine with this, but I'm a bit afraid 
that it will lead us to an awful lot of GUCs for simple things.

>> +                ereport(LOG,
>> +                        errmsg("backend ready for query. pid=%d. socket=%d. connection establishment times (ms):
total:%ld, fork: %ld, authentication: %ld",
 
>> +                               MyProcPid,
>> +                               (int) MyClientSocket->sock,
>>
>> Why expose the socket's file descriptor? I'm not sure how users would use that information.
>>
>>
>> Including the PID seems unnecessary since it's already available via log_line_prefix with %p?
> 
> Yeah, we would get things like:
> 
> [1111539] LOG:  connection received: host=[local]
> [1111539] LOG:  connection authenticated: user="postgres" method=trust
(/home/postgres/postgresql/pg_installed/pg18/data/pg_hba.conf:117)
> [1111539] LOG:  connection authorized: user=postgres database=postgres application_name=psql
> [1111539] LOG:  backend ready for query. pid=1111539. socket=9. connection establishment times (ms): total: 2, fork:
0,authentication: 0
 
> 
> I also wonder if "backend ready for query" is worth it. Maybe something like:
> 
> 2025-02-26 06:44:23.265 UTC [1111539] LOG:  connection establishment times (ms): total: 2, fork: 0, authentication:
0
> 
> would be good enough?
> 

Sounds definitely better to me.

> A few random comments:
> 
> === 1
> 
> +typedef struct ConnectionTiming
> +{
> +       instr_time      fork_duration;
> +       instr_time      auth_duration;
> +} ConnectionTiming;
> 
> As it's all about instr_time, I wonder if we could use an enum + array instead.
> That's probably just a matter of taste but that sounds more flexible to extend
> (should we want to add more timing in the future).
> 
> === 2
> 
> +ConnectionTiming conn_timing = {0};
> 
> There is no padding in ConnectionTiming and anyway we just access its fields
> so that's ok to initialize that way.
> 
> === 3
> 
> Add a few words in the log_connections GUC doc? (anyway we will have to if
> Fujii-san idea above about the timing is implemented)
> 
> === 4
> 
> +               /* Calculate total fork duration in child backend for logging */
> +               if (child_type == B_BACKEND)
> +               {
> +                       INSTR_TIME_SET_CURRENT(conn_timing.fork_duration);
> +                       INSTR_TIME_SUBTRACT(conn_timing.fork_duration,
> +                                                               ((BackendStartupData *) startup_data)->fork_time);
> +               }
> +
>                  /* Close the postmaster's sockets */
>                  ClosePostmasterPorts(child_type == B_LOGGER);
> 
> @@ -618,6 +630,14 @@ SubPostmasterMain(int argc, char *argv[])
>          /* Read in the variables file */
>          read_backend_variables(argv[2], &startup_data, &startup_data_len);
> 
> +       /* Calculate total fork duration in child backend for logging */
> +       if (child_type == B_BACKEND)
> +       {
> +               INSTR_TIME_SET_CURRENT(conn_timing.fork_duration);
> +               INSTR_TIME_SUBTRACT(conn_timing.fork_duration,
> +                               ((BackendStartupData *) startup_data)->fork_time);
> +       }
> 
> worth to add a helper function to avoid code duplication?
> 
> Regards,
> 


-- 
Guillaume Lelarge
Consultant
https://dalibo.com

Re: Log connection establishment timings

From

Melanie Plageman

Date:

26 February, 21:37:40

Thanks for the review!

On Tue, Feb 25, 2025 at 11:46 PM Fujii Masao
<masao.fujii@oss.nttdata.com> wrote:
>
> On 2025/02/26 6:36, Melanie Plageman wrote:
> > On Tue, Feb 25, 2025 at 3:23 PM Melanie Plageman
> > <melanieplageman@gmail.com> wrote:
>
> +       /* Capture time Postmaster initiates fork for logging */
> +       if (child_type == B_BACKEND)
> +               INSTR_TIME_SET_CURRENT(((BackendStartupData *) startup_data)->fork_time);
>
> When log_connections is enabled, walsender connections are also logged.
> However, with the patch, it seems the connection time for walsenders isn't captured.
> Is this intentional?

Ah, great point. It was not intentional. I've added a check for wal
sender to the attached v5.
Are these the only backend types that establish connections from outside?

This makes me wonder if I don't need these checks (for backend type)
before capturing the current time in PerformAuthentication() -- that
is, if they are performing authentication, aren't they inherently one
of these backend types?

> With the current patch, when log_connections is enabled, the connection time is always
> captured, and which might introduce performance overhead. No? Some users who enable
> log_connections may not want this extra detail and want to avoid such overhead.
> So, would it make sense to extend log_connections with a new option like "timing" and
> log the connection time only when "timing" is specified?

Ah yes, I did this intentionally originally because I thought someone
might change the value of log_connections in between the start and end
of the duration. I now see you cannot change log_connections after
connection start. So, I can guard these behind log_connections (done
in attached v5).

I hesitate to have a separate guc controlling whether or not we log
connection timing. If we add far more instances of getting the current
time, then perhaps it makes sense. But, as it is, we are adding six
system calls that take on the order of nanoseconds (esp if using
clock_gettime()), whereas emitting each log message -- which
log_connections allows -- will take on the order of micro or even
milliseconds.

> +                               ereport(LOG,
> +                                               errmsg("backend ready for query. pid=%d. socket=%d. connection
establishmenttimes (ms): total: %ld, fork: %ld, authentication: %ld", 
> +                                                          MyProcPid,
> +                                                          (int) MyClientSocket->sock,
>
> Why expose the socket's file descriptor? I'm not sure how users would use that information.

I originally included the socket fd because I thought we might end up
printing the times instead of the durations and then users would have
to parse them to get the durations and would need a way to uniquely
identify a connection. This would ideally be a combination of client
address, client port, server address, server port -- but those are
harder to print out (due to IP versions, etc) and harder to parse.

Also, I did notice other places printing the socket (like
BackendStartup() after forking).

Since this version is just printing one message, I have removed the socket fd.

> Including the PID seems unnecessary since it's already available via log_line_prefix with %p?

Ah, great point. I've removed that from the log message in the attached version

- Melanie

Attachment

v5-0001-Add-connection-establishment-duration-logging.patch

Re: Log connection establishment timings

From

Melanie Plageman

Date:

26 February, 21:45:39

Thanks for the continued review!

On Wed, Feb 26, 2025 at 2:41 AM Bertrand Drouvot
<bertranddrouvot.pg@gmail.com> wrote:
>
> On Wed, Feb 26, 2025 at 01:46:19PM +0900, Fujii Masao wrote:
> >
> > With the current patch, when log_connections is enabled, the connection time is always
> > captured, and which might introduce performance overhead. No? Some users who enable
> > log_connections may not want this extra detail and want to avoid such overhead.
> > So, would it make sense to extend log_connections with a new option like "timing" and
> > log the connection time only when "timing" is specified?
>
> +1, I also think it's a good idea to let users decide if they want the timing
> measurement overhead (and it's common practice with track_io_timing,
> track_wal_io_timing, the newly track_cost_delay_timing for example)

It seems to me like the extra timing collected and the one additional
log message isn't enough overhead to justify its own guc (for now).

> > Including the PID seems unnecessary since it's already available via log_line_prefix with %p?
>
> Yeah, we would get things like:
>
> [1111539] LOG:  connection received: host=[local]
> [1111539] LOG:  connection authenticated: user="postgres" method=trust
(/home/postgres/postgresql/pg_installed/pg18/data/pg_hba.conf:117)
> [1111539] LOG:  connection authorized: user=postgres database=postgres application_name=psql
> [1111539] LOG:  backend ready for query. pid=1111539. socket=9. connection establishment times (ms): total: 2, fork:
0,authentication: 0 
>
> I also wonder if "backend ready for query" is worth it. Maybe something like:
>
> 2025-02-26 06:44:23.265 UTC [1111539] LOG:  connection establishment times (ms): total: 2, fork: 0, authentication: 0
>
> would be good enough?

Yes, thank you. v5 attached in [1] changes the wording as you recommend..

> +typedef struct ConnectionTiming
> +{
> +       instr_time      fork_duration;
> +       instr_time      auth_duration;
> +} ConnectionTiming;
>
> As it's all about instr_time, I wonder if we could use an enum + array instead.
> That's probably just a matter of taste but that sounds more flexible to extend
> (should we want to add more timing in the future).

I think we can change it later if we add many more. For now I prefer
the clarity of accessing members by name. Especially because we don't
have any code yet that loops through all of them or anything like
that.

> +ConnectionTiming conn_timing = {0};
>
> There is no padding in ConnectionTiming and anyway we just access its fields
> so that's ok to initialize that way.

Yes, this properly zero initializes the struct. In fact it shouldn't
be needed since a global like this should be zero initialized. But all
of the globals defined above conn_timing zero initialize themselves,
so I thought I would be consistent with them.

> Add a few words in the log_connections GUC doc? (anyway we will have to if
> Fujii-san idea above about the timing is implemented)

I forgot to do this in v5 attached in [1]. Let me go ahead and do this next.

> +               /* Calculate total fork duration in child backend for logging */
> +               if (child_type == B_BACKEND)
> +               {
> +                       INSTR_TIME_SET_CURRENT(conn_timing.fork_duration);
> +                       INSTR_TIME_SUBTRACT(conn_timing.fork_duration,
> +                                                               ((BackendStartupData *) startup_data)->fork_time);
> +               }
> +
>                 /* Close the postmaster's sockets */
>                 ClosePostmasterPorts(child_type == B_LOGGER);
>
> @@ -618,6 +630,14 @@ SubPostmasterMain(int argc, char *argv[])
>         /* Read in the variables file */
>         read_backend_variables(argv[2], &startup_data, &startup_data_len);
>
> +       /* Calculate total fork duration in child backend for logging */
> +       if (child_type == B_BACKEND)
> +       {
> +               INSTR_TIME_SET_CURRENT(conn_timing.fork_duration);
> +               INSTR_TIME_SUBTRACT(conn_timing.fork_duration,
> +                               ((BackendStartupData *) startup_data)->fork_time);
> +       }
>
> worth to add a helper function to avoid code duplication?

I've added INSTR_TIME_GET_DURATION_SINCE(start_time). Which I like
because it seems generally useful. It does not however cut down on
LOC, so I'm somewhat on the fence.

- Melanie

[1] https://www.postgresql.org/message-id/CAAKRu_Y9sgZAWCiQoHtpwx6Mv28fBGav5ztrWyeSrx%2BB%3DACN6g%40mail.gmail.com

Re: Log connection establishment timings

From

Melanie Plageman

Date:

26 February, 22:29:33

On Wed, Feb 26, 2025 at 1:45 PM Melanie Plageman
<melanieplageman@gmail.com> wrote:
>
> Thanks for the continued review!
>
> On Wed, Feb 26, 2025 at 2:41 AM Bertrand Drouvot
> <bertranddrouvot.pg@gmail.com> wrote:
>
> > Add a few words in the log_connections GUC doc? (anyway we will have to if
> > Fujii-san idea above about the timing is implemented)
>
> I forgot to do this in v5 attached in [1]. Let me go ahead and do this next.

I took a stab at this in attached v6. I feel that what I have is a bit
stilted, but I'm not sure how to fix it.

- Melanie

Attachment

v6-0001-Add-connection-establishment-duration-logging.patch

Re: Log connection establishment timings

From

Bertrand Drouvot

Date:

27 February, 09:50:41

Hi,

On Wed, Feb 26, 2025 at 01:45:39PM -0500, Melanie Plageman wrote:
> Thanks for the continued review!
> 
> On Wed, Feb 26, 2025 at 2:41 AM Bertrand Drouvot
> <bertranddrouvot.pg@gmail.com> wrote:
> >
> > On Wed, Feb 26, 2025 at 01:46:19PM +0900, Fujii Masao wrote:
> > >
> > > With the current patch, when log_connections is enabled, the connection time is always
> > > captured, and which might introduce performance overhead. No? Some users who enable
> > > log_connections may not want this extra detail and want to avoid such overhead.
> > > So, would it make sense to extend log_connections with a new option like "timing" and
> > > log the connection time only when "timing" is specified?
> >
> > +1, I also think it's a good idea to let users decide if they want the timing
> > measurement overhead (and it's common practice with track_io_timing,
> > track_wal_io_timing, the newly track_cost_delay_timing for example)
> 
> It seems to me like the extra timing collected and the one additional
> log message isn't enough overhead to justify its own guc (for now).

Agree. IIUC, I think that Fujii-san's idea was to extend log_connections with
a new option "timing" (i.e move it from ConfigureNamesBool to say
ConfigureNamesEnum with say on, off and timing?). I think that's a good idea.

I just did a quick check and changing a GUC from ConfigureNamesBool to 
ConfigureNamesEnum is something that has already been done in the past (see
240067b3b0f and ffd37740ee6 for example).

In my previous up-thead message, I did not mean to suggest to add a new GUC,
just saying that when new "timing" is measured then users have the choice to
enable or disable it.

> > > Including the PID seems unnecessary since it's already available via log_line_prefix with %p?
> >
> > Yeah, we would get things like:
> >
> > [1111539] LOG:  connection received: host=[local]
> > [1111539] LOG:  connection authenticated: user="postgres" method=trust
(/home/postgres/postgresql/pg_installed/pg18/data/pg_hba.conf:117)
> > [1111539] LOG:  connection authorized: user=postgres database=postgres application_name=psql
> > [1111539] LOG:  backend ready for query. pid=1111539. socket=9. connection establishment times (ms): total: 2,
fork:0, authentication: 0
 
> >
> > I also wonder if "backend ready for query" is worth it. Maybe something like:
> >
> > 2025-02-26 06:44:23.265 UTC [1111539] LOG:  connection establishment times (ms): total: 2, fork: 0, authentication:
0
> >
> > would be good enough?
> 
> Yes, thank you. v5 attached in [1] changes the wording as you recommend..

Thanks for the updated version!

> > +typedef struct ConnectionTiming
> > +{
> > +       instr_time      fork_duration;
> > +       instr_time      auth_duration;
> > +} ConnectionTiming;
> >
> > As it's all about instr_time, I wonder if we could use an enum + array instead.
> > That's probably just a matter of taste but that sounds more flexible to extend
> > (should we want to add more timing in the future).
> 
> I think we can change it later if we add many more. For now I prefer
> the clarity of accessing members by name. Especially because we don't
> have any code yet that loops through all of them or anything like
> that.

Yeah makes sense.

> > Add a few words in the log_connections GUC doc? (anyway we will have to if
> > Fujii-san idea above about the timing is implemented)
> 
> I took a stab at this in attached v6. I feel that what I have is a bit
> stilted, but I'm not sure how to fix it.

Yeah, that might be easier to reason about if we're going with Fujii-san
suggestion to extend log_connections with a new option?

> > +               /* Calculate total fork duration in child backend for logging */
> > +               if (child_type == B_BACKEND)
> > +               {
> > +                       INSTR_TIME_SET_CURRENT(conn_timing.fork_duration);
> > +                       INSTR_TIME_SUBTRACT(conn_timing.fork_duration,
> > +                                                               ((BackendStartupData *) startup_data)->fork_time);
> > +               }
> > +
> >                 /* Close the postmaster's sockets */
> >                 ClosePostmasterPorts(child_type == B_LOGGER);
> >
> > @@ -618,6 +630,14 @@ SubPostmasterMain(int argc, char *argv[])
> >         /* Read in the variables file */
> >         read_backend_variables(argv[2], &startup_data, &startup_data_len);
> >
> > +       /* Calculate total fork duration in child backend for logging */
> > +       if (child_type == B_BACKEND)
> > +       {
> > +               INSTR_TIME_SET_CURRENT(conn_timing.fork_duration);
> > +               INSTR_TIME_SUBTRACT(conn_timing.fork_duration,
> > +                               ((BackendStartupData *) startup_data)->fork_time);
> > +       }
> >
> > worth to add a helper function to avoid code duplication?
> 
> I've added INSTR_TIME_GET_DURATION_SINCE(start_time). Which I like
> because it seems generally useful.

Great idea! Could probably be used in other places but I did not check and
it's outside the scope of this thread anyway.

> It does not however cut down on LOC, so I'm somewhat on the fence.

I think that's somehow also around code maintenance (not only LOC), say for example
if we want to add more "child_type" in the check (no need to remember to update both
locations).

Regards,

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

Re: Log connection establishment timings

From

Melanie Plageman

Date:

27 February, 19:08:04

On Thu, Feb 27, 2025 at 1:50 AM Bertrand Drouvot
<bertranddrouvot.pg@gmail.com> wrote:
>
> Agree. IIUC, I think that Fujii-san's idea was to extend log_connections with
> a new option "timing" (i.e move it from ConfigureNamesBool to say
> ConfigureNamesEnum with say on, off and timing?). I think that's a good idea.
>
> I just did a quick check and changing a GUC from ConfigureNamesBool to
> ConfigureNamesEnum is something that has already been done in the past (see
> 240067b3b0f and ffd37740ee6 for example).
>
> In my previous up-thead message, I did not mean to suggest to add a new GUC,
> just saying that when new "timing" is measured then users have the choice to
> enable or disable it.

I was just talking to Andres off-list and he mentioned that the volume
of log_connections messages added in recent releases can really be a
problem for users. He said ideally we would emit one message which
consolidated these (and make sure we did so for failed connections too
detailing the successfully completed stages).

However, since that is a bigger project (with more refactoring, etc),
he suggested that we change log_connections to a GUC_LIST
(ConfigureNamesString) with options like "none", "received,
"authenticated", "authorized", "all".

Then we could add one like "established" for the final message and
timings my patch set adds. I think the overhead of an additional log
message being emitted probably outweighs the overhead of taking those
additional timings.

String GUCs are a lot more work than enum GUCs, so I was thinking if
there is a way to do it as an enum.

I think we want the user to be able to specify a list of all the log
messages they want included, not just have each one include the
previous ones. So, then it probably has to be a list right? There is
no good design that would fit as an enum.

> > I've added INSTR_TIME_GET_DURATION_SINCE(start_time). Which I like
> > because it seems generally useful.
>
> Great idea! Could probably be used in other places but I did not check and
> it's outside the scope of this thread anyway.
>
> > It does not however cut down on LOC, so I'm somewhat on the fence.
>
> I think that's somehow also around code maintenance (not only LOC), say for example
> if we want to add more "child_type" in the check (no need to remember to update both
> locations).

I didn't include checking the child_type in that function since it is
unrelated to instr_time, so it sadly wouldn't help with that. We could
macro-ize the child_type check were we to add another child_type.

- Melanie

Re: Log connection establishment timings

From

Andres Freund

Date:

27 February, 19:14:56

Hi,

On 2025-02-27 06:50:41 +0000, Bertrand Drouvot wrote:
> On Wed, Feb 26, 2025 at 01:45:39PM -0500, Melanie Plageman wrote:
> > Thanks for the continued review!
> >
> > On Wed, Feb 26, 2025 at 2:41 AM Bertrand Drouvot
> > <bertranddrouvot.pg@gmail.com> wrote:
> > >
> > > On Wed, Feb 26, 2025 at 01:46:19PM +0900, Fujii Masao wrote:
> > > >
> > > > With the current patch, when log_connections is enabled, the connection time is always
> > > > captured, and which might introduce performance overhead. No? Some users who enable
> > > > log_connections may not want this extra detail and want to avoid such overhead.
> > > > So, would it make sense to extend log_connections with a new option like "timing" and
> > > > log the connection time only when "timing" is specified?
> > >
> > > +1, I also think it's a good idea to let users decide if they want the timing
> > > measurement overhead (and it's common practice with track_io_timing,
> > > track_wal_io_timing, the newly track_cost_delay_timing for example)
> >
> > It seems to me like the extra timing collected and the one additional
> > log message isn't enough overhead to justify its own guc (for now).
>
> Agree. IIUC, I think that Fujii-san's idea was to extend log_connections with
> a new option "timing" (i.e move it from ConfigureNamesBool to say
> ConfigureNamesEnum with say on, off and timing?). I think that's a good idea.

I don't think the timing overhead is a relevant factor here - compared to the
fork of a new connection or performing authentication the cost of taking a few
timestamps is neglegible. A timestamp costs 10s to 100s of cycles, a fork many
many millions. Even if you have a really slow timestamp function, it's still
going to be way way cheaper.

Greetings,

Andres Freund

Re: Log connection establishment timings

From

Andres Freund

Date:

27 February, 19:30:09

Hi,

On 2025-02-27 11:08:04 -0500, Melanie Plageman wrote:
> I was just talking to Andres off-list and he mentioned that the volume
> of log_connections messages added in recent releases can really be a
> problem for users.

For some added color: I've seen plenty systems where almost all the log volume
is log_connection messages, which they *have* to enable for various regulatory
reasons.  It'd still be a lot if we just emitted one message for each
connection, but logging three (and possibly four with $thread), for each
connection makes it substantially worse.

> He said ideally we would emit one message which consolidated these (and make
> sure we did so for failed connections too detailing the successfully
> completed stages).

A combined message would also not *quite* replace all use-cases, e.g. if you
want to debug arriving connections or auth problems you do want the additional
messages.  But yea, for normal operation, I do think most folks want just one
message.

> However, since that is a bigger project (with more refactoring, etc),
> he suggested that we change log_connections to a GUC_LIST
> (ConfigureNamesString) with options like "none", "received,
> "authenticated", "authorized", "all".

Yep.

> Then we could add one like "established" for the final message and
> timings my patch set adds. I think the overhead of an additional log
> message being emitted probably outweighs the overhead of taking those
> additional timings.

To bikeshed a bit: "established" could be the TCP connection establishment
just as well. I'd go for "completed" or "timings".

> String GUCs are a lot more work than enum GUCs, so I was thinking if
> there is a way to do it as an enum.
> 
> I think we want the user to be able to specify a list of all the log
> messages they want included, not just have each one include the
> previous ones. So, then it probably has to be a list right? There is
> no good design that would fit as an enum.

I don't see a way to comfortably shove this into an enum either.

Greetings,

Andres Freund

Re: Log connection establishment timings

From

Melanie Plageman

Date:

28 February, 01:55:19

On Thu, Feb 27, 2025 at 11:30 AM Andres Freund <andres@anarazel.de> wrote:
>
> On 2025-02-27 11:08:04 -0500, Melanie Plageman wrote:
>
> > However, since that is a bigger project (with more refactoring, etc),
> > he suggested that we change log_connections to a GUC_LIST
> > (ConfigureNamesString) with options like "none", "received,
> > "authenticated", "authorized", "all".
>
> Yep.

I've done a draft of this in attached v7 (see 0001). It still needs
polishing (e.g. I need to figure out where to put the new guc hook
functions and enums and such), but I want to see if this is a viable
direction forward.

I'm worried the list of possible connection log messages could get
unwieldy if we add many more.

- Melanie

On Fri, Feb 28, 2025 at 12:54 AM Bertrand Drouvot
<bertranddrouvot.pg@gmail.com> wrote:
>
> On Thu, Feb 27, 2025 at 05:55:19PM -0500, Melanie Plageman wrote:
> > It still needs polishing (e.g. I need to figure out where to put the new guc hook
> > functions and enums and such)
>
> yeah, I wonder if it would make sense to create new dedicated "connection_logging"
> file(s).

I think for now there isn't enough for a new file. I think these are
probably okay in postmaster.c since this has to do with postmaster
starting new connections.

> > I'm worried the list of possible connection log messages could get
> > unwieldy if we add many more.
>
> Thinking out loud, I'm not sure we'd add "many more" but maybe what we could do
> is to introduce some predefined groups like:
>
> 'basic' (that would be equivalent to 'received, + timings introduced in 0002')
> 'security' (equivalent to 'authenticated,authorized')
>
> Not saying we need to create this kind of predefined groups now, just an idea
> in case we'd add many more: that could "help" the user experience, or are you
> more concerned about the code maintenance?

I was more worried about the user having to provide very long lists.
But groupings could be a sensible solution in the future.

> Just did a quick test, (did not look closely at the code), and it looks like
> that:
>
> 'all': does not report the "received" (but does report authenticated and authorized)
> 'received': does not work?
> 'authenticated': works
> 'authorized': works

Thanks for testing! Ouch, there were many bugs in that prototype. My
enums were broken and a few other things.

I found some bugs in 0002 as well.  Attached v8 fixes the issues I found so far.

We have to be really careful about when log_connections is actually
set before we use it -- I fixed some issues with that.

I decided to move the creation_time out of ClientSocket and into
BackendStartupData, but that meant I had to save it in the
ConnectionTiming because we don't have access to the
BackendStartupData anymore in PostgresMain(). That means
ConnectionTiming is now a mixture of times and durations. I think that
should be okay (i.e. not too confusing and gross), but I'm not sure.
It is called ConnectionTiming and not ConnectionDuration, after all.

- Melanie

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.pg@gmail.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

Attachment

v9-0001-Add-connection-establishment-duration-logging.patch

Re: Log connection establishment timings

From

Melanie Plageman

Date:

05 March, 02:30:27

Thanks so much for your review!

On Mon, Mar 3, 2025 at 12:08 PM Fujii Masao <masao.fujii@oss.nttdata.com> wrote:
>
>
> > +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 guess that check_log_connections() is implemented to use SplitGUCList()
> because check_debug_io_direct() does too. However, according to the comment for
> SplitGUCList() — "This is used to split the value of a GUC_LIST_QUOTE GUC variable",
> it seems more appropriate to use SplitIdentifierString() instead,
> like other options such as log_destination, since log_connections is not
> a GUC_LIST_QUOTE GUC.

Ah, this was a very good catch. It seems like actually debug_io_direct
should use that too. Now I'm not using the string list method anymore,
but thanks for catching this.

> +#log_connections = ''
>
> It would also be helpful to include all valid values in a comment
> within postgresql.conf.sample, making it easier for users to configure.

I haven't updated postgresql.conf.sample in v9 proposed here [1]. But
now that log_connections has three options, do you think I should
specify all three? It used to only specify off, but probably because
it was obvious that "on" was the opposite of "off".

- Melanie

[1] https://www.postgresql.org/message-id/CAAKRu_aoerKAOYKkc7-JGq2bixrYTbViK_7EeLNhFUGoT_omFw%40mail.gmail.com

Re: Log connection establishment timings

From

Melanie Plageman

Date:

05 March, 02:34:47

On Mon, Mar 3, 2025 at 11:45 PM Fujii Masao <masao.fujii@oss.nttdata.com> wrote:
>
> When log_connection is empty string in postgresql.conf and I ran
> "psql -d "options=-clog_connections=all"", I got the following log message.
> You can see the total duration in this message is unexpected.
> It looks like this happens because creation_time wasn’t collected,
> as log_connections was empty before the fork.
>
>      LOG:  connection establishment times (ms): total: 1148052469, fork: 0, authentication: 0

Wow, yes, thanks for catching that. I didn't remember that you could
pass startup options like that. For that example,
process_startup_options() actually happens so late that we do not have
the intended value of log_connections until after we've already taken
all of the timings. As such, I propose we take those measurements
unconditionally (since we established they aren't too expensive when
compared to the cost of actually forking the backend) and then only
emit the message if log_connections is "timings". We are guaranteed to
have the intended value of log_connections by the time we are
ready-for-query. I've implemented this in [1].

- Melanie

[1] https://www.postgresql.org/message-id/CAAKRu_aoerKAOYKkc7-JGq2bixrYTbViK_7EeLNhFUGoT_omFw%40mail.gmail.com

Re: Log connection establishment timings

From

Jacob Champion

Date:

05 March, 02:43:41

On Tue, Mar 4, 2025 at 3:25 PM Melanie Plageman
<melanieplageman@gmail.com> wrote:
>
> I don't
> see any other TAP tests that are testing connections. There are a
> whole bunch of auth tests, I suppose.

I was going to suggest src/test/authentication, yeah. Not perfect, but
better than nothing?

--Jacob

Re: Log connection establishment timings

From

Bertrand Drouvot

Date:

05 March, 11:53:15

Hi,

On Tue, Mar 04, 2025 at 05:47:26PM -0500, Melanie Plageman wrote:
> On Mon, Mar 3, 2025 at 9:07 AM Bertrand Drouvot
> <bertranddrouvot.pg@gmail.com> wrote:
> >
> > I did not imagine that much ;-) I was just seeing this code being duplicated
> > and just thought about to avoid the duplication. But now that I read your comments
> > above then I think we could just macro-ize the child_type check (as you mentioned
> > up-thread). That would avoid the risk to forget to update the 3 locations doing the
> > exact same check should we add a new child type in the game.
> 
> Is there a word we could use to describe what B_BACKEND and
> B_WAL_SENDER have in common? They are the only backend types that will
> go through the kind of external connection establishment steps (I
> think), but I don't know a very accurate way to make that distinction
> (which is required to come up with a useful macro name).

Yeah, what about IS_CONNECTION_TIMED_BACKEND?

Regards,

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

Re: Log connection establishment timings

From

Bertrand Drouvot

Date:

05 March, 13:36:17

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.pg@gmail.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

Re: Log connection establishment timings

From

Melanie Plageman

Date:

05 March, 18:46:22

On Wed, Mar 5, 2025 at 5:36 AM Bertrand Drouvot
<bertranddrouvot.pg@gmail.com> wrote:
>
> 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.

Yes, this is a bit unfortunate, but I don't think we can accept t, f,
fa, etc. There is precedent for changing a boolean GUC to an enum --
synchronous_commit was like this.

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

Yea, I don't think it makes sense to do more than the ones included in
that array.

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

Good idea. I've done this in my branch which I will post as patches later.

This morning, Andres reminded me off-list that we actually can still
support unquoted off and on values (as well as other single word
tokens like true, 1, etc) even if we transitioned to a string/list GUC
type. He also pointed out that tab-completion would be basically
useless for log_connections since it is not allowed to be set once the
connection is already established.

As such, I wonder if my PGC_SET idea is not worth the effort and I
should revise the earlier patch version which specified the stages but
allow for on, off, true, yes, 1 for backwards compatibility and not
include disconnections (so we don't remove the log_disconnections GUC
this release).

That would allow
log_connections = on
log_connections = off
as well as
log_connections = 'received, authenticated'
and even
log_connections = received

- Melanie

Re: Log connection establishment timings

From

Melanie Plageman

Date:

06 March, 02:40:10

On Wed, Mar 5, 2025 at 10:46 AM Melanie Plageman
<melanieplageman@gmail.com> wrote:
>
> As such, I wonder if my PGC_SET idea is not worth the effort and I
> should revise the earlier patch version which specified the stages but
> allow for on, off, true, yes, 1 for backwards compatibility and not
> include disconnections (so we don't remove the log_disconnections GUC
> this release).

Okay! Attached v10 does this. It turns log_connections into a string
but supports all the common values of the current log_connections
boolean.

So, you can specify
   log_connections = authorized,authenticated
   log_connections = 'all'
   log_connections = on
   etc
And only 'all' has to be quoted when not specified as a startup option
(which is true for other enum gucs that have 'all' as an option
because ALL is a Postgres keyword).

I've left log_disconnections alone.

I still need to comprehensively manually test it myself (so there
might still be bugs) and write a bit of test coverage for the new
values. The docs can probably also use some more massaging.

But, this is the first version of the patch where I am happy with the
interface and with the code. It isn't a breaking change (since on,
off, true, false, etc still work), so I think it is still okay to
target 18.

I went back through the thread and tried to be sure I addressed all of
the outstanding review comments on previous versions (since I
resurrected some previously dead patch features), but I can't be sure
I caught it all. Please don't hesitate to call out anything I missed.

I didn't enumerate all the possibilities in postgresql.conf.sample as
Fujii-san recommended in a previous review, because I didn't see many
other enum GUCs doing that. I am open to changing that if folks feel
strongly, though.

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?

- Melanie

Attachment

Re: Log connection establishment timings

From

Bertrand Drouvot

Date:

06 March, 17:56:16

Hi,

On Wed, Mar 05, 2025 at 06:40:10PM -0500, Melanie Plageman wrote:
> On Wed, Mar 5, 2025 at 10:46 AM Melanie Plageman
> <melanieplageman@gmail.com> wrote:
> >
> > As such, I wonder if my PGC_SET idea is not worth the effort and I
> > should revise the earlier patch version which specified the stages but
> > allow for on, off, true, yes, 1 for backwards compatibility and not
> > include disconnections (so we don't remove the log_disconnections GUC
> > this release).
> 
> Okay! Attached v10 does this.

Great, thanks for it!

> It turns log_connections into a string
> but supports all the common values of the current log_connections
> boolean.
> 
> So, you can specify
>    log_connections = authorized,authenticated

Yeah, when used like psql -d "options=-clog_connections=authorized,authenticated"
but needs to be log_connections = 'authorized,authenticated' in the postgresql.conf
file. That makes fully sense.

> But, this is the first version of the patch where I am happy with the
> interface and with the code. It isn't a breaking change (since on,
> off, true, false, etc still work), so I think it is still okay to
> target 18.

A few comments about 0001:

=== 1

we have this:

+       /* For backwards compatability, 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},
+       };

and

+typedef enum LogConnectionOption
+{
+       LOG_CONNECTION_RECEIVED = (1 << 0),
+       LOG_CONNECTION_AUTHENTICATED = (1 << 1),
+       LOG_CONNECTION_AUTHORIZED = (1 << 2),
+       LOG_CONNECTION_ON =
+               LOG_CONNECTION_RECEIVED |
+               LOG_CONNECTION_AUTHENTICATED |
+               LOG_CONNECTION_AUTHORIZED,
+       LOG_CONNECTION_ALL =
+               LOG_CONNECTION_ON,
+} LogConnectionOption;

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;

=== 2

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

=== 3

+       /* If an empty string was passed, we're done. */
+       if (list_length(elemlist) == 0)
+               return 0;
+
+       /*
+        * Now check for the backwards compatability options. They must always be
+        * specified on their own, so we error out if the first option is a
+        * backwards compatability option and other options are also specified.
+        */
+       item = linitial(elemlist);
+
+       for (size_t i = 0; i < lengthof(compat_options); i++)
+       {
+               struct config_enum_entry option = compat_options[i];
+
+               if (pg_strcasecmp(item, option.name) != 0)
+                       continue;
+
+               if (list_length(elemlist) > 1)
+               {

what about storing the list_length(elemlist) at the start to avoid the multiple
list_length(elemlist) calls?

=== 4

+       /* If an empty string was passed, we're done. */

s/done./done/? (Looking at the one line comments around)

=== 5

+       /* Now check the stage-specific options. */

s/options./options/? (Looking at the one line comments around)

=== 6

+       /* For backwards compatability, we accept these tokens by themselves */

Typo: compatability/compatibility

, seen multiple times:

$ git grep compatability
doc/src/sgml/config.sgml:        For the purposes of backwards compatability, <literal>on</literal>,
src/backend/tcop/backend_startup.c:     /* For backwards compatability, we accept these tokens by themselves */
src/backend/tcop/backend_startup.c:      * Now check for the backwards compatability options. They must always be
src/backend/tcop/backend_startup.c:      * backwards compatability option and other options are also specified.
src/include/tcop/backend_startup.h: * ON is backwards compatability alias for the connection events that were

=== 7

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

The logic in 0001 looks good to me, also I did a few tests and that looks ok
seen from here.

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

I think I could vote for "ready_for_query" should the GUC be log_connection_stages
(and not log_connections).

I also think that we can keep "reported_first_ready_for_query", "send_ready_for_query"
in the code though (even if the GUC option is changed to "timings").

A few comments about 0002:

==== 8

+       if (IsConnectionBackend(child_type))

IsConnectionBackend is fine by me.

=== 9

+  /* Calculate fork duration since we have start and end times. */

s/times./times/? (Looking at the one line comments around)

=== 10

+  /* Will be used to calculate total connection setup duration. */

s/duration./duration/? (Looking at the one line comments around)

=== 11

+       /* How long it took the backend to be forked. */

s/forked./forked/? (Looking at the one line comments around)

=== 12

+      if (!reported_first_ready_for_query &&
+          log_connections & LOG_CONNECTION_READY_FOR_QUERY &&
+          IsConnectionBackend(MyBackendType))

same as comment === 2 above.

Regards,

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

Re: Log connection establishment timings

From

Melanie Plageman

Date:

06 March, 19:41:03

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.pg@gmail.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

Attachment

Re: Log connection establishment timings

From

Andres Freund

Date:

06 March, 22:10:47

Hi,

On 2025-01-20 15:01:38 +0000, Bertrand Drouvot wrote:
> Regarding the TimestampTz vs instr_time choice, we have things like:
> 
> + TimestampTz fork_time = ((BackendStartupData *) startup_data)->fork_time;
> + TimestampTz cur_time = GetCurrentTimestamp();
> +
> + conn_timing.fork_duration = TimestampDifferenceMicroseconds(fork_time,
> +                                                             cur_time);
> 
> but looking at TimestampDifferenceMicroseconds():
> 
> "
>     /* If start_time is in the future or now, no time has elapsed */
>     if (start_time >= stop_time)
>         return 0;
> "
> 
> I think that it can happen due to time changes.

It shouldn't during proper operation, the time should be accellerated or
slowed down, but not have backwards jumps.

> So with TimestampTz, we would:
> 
> 1. return 0 if we moved the time backward
> 2. provide an inflated duration including the time jump (if the time move
> forward).
> 
> But with instr_time (and on systems that support CLOCK_MONOTONIC) then
> pg_clock_gettime_ns() should not be affected by system time change IIUC.

It still does jump around a bit on some systems, even if it shouldn't. It's
not at all rare to see time distontinuities when getting scheduled on another
socket than before or when a VM got migrated. It shouldn't happen, but does.

> Though time changes are "rare", given the fact that those metrics could provide
> "inaccurate" measurements during that particular moment (time change) then it
> might be worth considering instr_time instead for this particular metric.

We calculate the times for log_min_duration_statement etc via
GetCurrentTimestamp(), I don't think it's worth worrying about that here.

I think it'd be better to use absolute times and store them as such in
ConnectionTimes or whatever. That way we have information about when a
connection was established for some future SQL functions and for debugging
problems.

Greetings,

Andres Freund

Re: Log connection establishment timings

From

Melanie Plageman

Date:

07 March, 02:16:07

On Thu, Mar 6, 2025 at 2:10 PM Andres Freund <andres@anarazel.de> wrote:
>
> I think it'd be better to use absolute times and store them as such in
> ConnectionTimes or whatever. That way we have information about when a
> connection was established for some future SQL functions and for debugging
> problems.

Attached v12 does this (uses timestamps instead of instr_time).

I've done some assorted cleanup. Most notably:

I removed LOG_CONNECTION_NONE because it could lead to wrong results
to have a bitmask with a flag value that is 0 (it could be set at the
same time other flags are set, so you could never use it correctly).

I updated the tests and moved them from the postmaster test suite to
the authentication test suite. They seemed like a slightly better fit
there.

I changed the user facing references to ready-for-query to
ready-to-use (it seemed less confusing).

I changed the process creation duration in the EXEC_BACKEND case to
_not_ include the overhead of copying data from shared memory and
reloading GUCs and the other setup done to get the backend in the
right state. Jacob at some point had asked about this, and I didn't
have a satisfactory answer. I'm not really sure what would be more
useful to end users.

- Melanie

Thanks for the review!

On Fri, Mar 7, 2025 at 2:08 AM Fujii Masao <masao.fujii@oss.nttdata.com> wrote:
>
> With the patch, any unambiguous prefix of a valid boolean value,
> like 'y', is no longer accepted even though it's currently valid
> for boolean GUCs. I don’t have a strong opinion on whether
> we should maintain compatibility for this, but I wanted to
> mention it for the record. If we do, we might need to use
> parse_bool() to interpret the values.

Indeed. In fact, in master, any substring of true/yes/false/no would
be accepted. So I could set log_connections = tr;
It's true that with this patch only on,off,true,false,1,0,yes,no would
be supported. But I think that is okay. If we allow arbitrary
unambiguous substrings of the previously accepted values, it limits
what future log_connections options we can add (they couldn't clash
with any of those substrings or introduce ambiguity). I think it's
better we just draw a line now.

There is one complication, the boolean GUC infrastructure parses those
inputs but then the output is always "on" or "off" in this case. So,
on master if you set log_connections=1 and then do "show
log_connections" it will display "on". With this patch it would
display 1. We may be able to solve that with a show hook, but my
instinct is that that is not worth it. What do you think?

> + * NONE is an alias for when no connection logging should be done.
>
> The comment about "NONE" should be removed since LOG_CONNECTION_NONE was deleted.

Thanks! Fixed in attached v13.

> +typedef enum LogConnectionOption
> +{
> +       LOG_CONNECTION_RECEIVED = (1 << 0),
> +       LOG_CONNECTION_AUTHENTICATED = (1 << 1),
>
> Since the GUC is named log_connections, I'm tempted to name
> LOG_CONNECTIONS_XXX and LogConnectionsOption here instead.
> This is just a suggestion. If others prefer the current names,
> I’m fine with that.

For the enum and its values, I prefer the singular. log_connections is
about logging all connections. However, when we use these enums, it is
about logging a particular connection, so the singular feels more
appropriate.

> Comments for v2:
>
> +       if (IsConnectionBackend(child_type))
> +               conn_timing.fork_end = GetCurrentTimestamp();
>
> In SubPostmasterMain(), GetCurrentTimestamp() is called twice to
> set fork_end. It seems unnecessary. We can remove the above call?

Whoops! Thanks for catching this. Fixed in attached v12.

> +       /* Capture authentication start time for logging */
> +       conn_timing.auth_start = GetCurrentTimestamp();
>
> In the EXEC_BACKEND case, the authentication start time differs
> from when the authentication timeout begins. But shouldn't these
> be the same?

Good point. At some point, I thought maybe it made sense to include
the EXEC_BACKEND-specific setup stuff in the authentication duration
since it is one of the overheads of doing authentication on an
EXEC_BACKEND backend. But, now I realize you are right -- the user
wants to know, if, for example, something weird is happening in a
library somewhere that is making authentication really slow -- not how
long it took to reload the HBA file. I've changed it as you suggested.

An unrelated note about the attached v13:
I changed the language from log_connections "stages" to "options" and
"aspects" depending on the context. I also changed the name of the
option introduced in 0002 to "durations".

I'm a bit torn about having the tests in authentication/001_password.
On the one hand, it doesn't make sense to make a separate test file
and initialize a new postgres just to test two or three options of one
GUC. On the other hand, these tests don't fit very well in any
existing test file I could find. Maybe it is fine that they are in a
file about testing password authentication...

- Melanie

On Mon, Mar 10, 2025 at 5:03 PM Daniel Gustafsson <daniel@yesql.se> wrote:
>
> > On 7 Mar 2025, at 23:08, Melanie Plageman <melanieplageman@gmail.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

Attachment

Re: Log connection establishment timings

From

Melanie Plageman

Date:

12 March, 18:43:17

On Tue, Mar 11, 2025 at 6:27 PM Melanie Plageman
<melanieplageman@gmail.com> wrote:
>
> 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've committed this and marked it as such in the CF app.
Thanks to everyone for the review.

- Melanie