Re: Log connection establishment timings

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