Re: Log connection establishment timings

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(at)gmail(dot)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