Message-ID: <a495c50c-1f8b-4d9c-b1f2-729c536f318e@dalibo.com>
Date: Wed, 26 Feb 2025 14:22:32 +0100
MIME-Version: 1.0
User-Agent: Mozilla Thunderbird
Subject: Re: Log connection establishment timings
To: pgsql-hackers@lists.postgresql.org
References: <CAAKRu_b_smAHK0ZjrnL5GRxnAVWujEXQWpLXYzGbmpcZd3nLYw@mail.gmail.com>
 <CAECtzeW3bFOT8v_th9hu6O9c0p+yNkD0ceBneWOtXYcwVd73rA@mail.gmail.com>
 <Z45lUorFBcmCKxp7@ip-10-97-1-34.eu-west-3.compute.internal>
 <CAAKRu_YrNsA7-v5L9d318XZu+tPqcxp+ctCGy2EGYrSt69ON=A@mail.gmail.com>
 <CAAKRu_aV+B2yLpkcfh06tJV7XQPodjasxQ=XKh+MjD8ixkXwrA@mail.gmail.com>
 <65fe2d68-a214-40f0-80a8-56ca7323ad5c@oss.nttdata.com>
 <Z77Fxf49c+LIW74a@ip-10-97-1-34.eu-west-3.compute.internal>
Content-Language: fr
From: Guillaume Lelarge <guillaume.lelarge@dalibo.com>
Organization: Dalibo
In-Reply-To: <Z77Fxf49c+LIW74a@ip-10-97-1-34.eu-west-3.compute.internal>
Content-Type: text/plain; charset=UTF-8; format=flowed
Content-Transfer-Encoding: 8bit
Archived-At: <https://www.postgresql.org/message-id/a495c50c-1f8b-4d9c-b1f2-729c536f318e%40dalibo.com>
Precedence: bulk

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