Message-ID: <65fe2d68-a214-40f0-80a8-56ca7323ad5c@oss.nttdata.com>
Date: Wed, 26 Feb 2025 13:46:19 +0900
MIME-Version: 1.0
User-Agent: Mozilla Thunderbird
Subject: Re: Log connection establishment timings
To: Melanie Plageman <melanieplageman@gmail.com>,
 Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
Cc: Guillaume Lelarge <guillaume@lelarge.info>,
 Pg Hackers <pgsql-hackers@postgresql.org>,
 Daniel Gustafsson <daniel@yesql.se>, andrey.chudnovskiy@microsoft.com,
 Jelte Fennema-Nio <postgres@jeltef.nl>,
 Jacob Champion <jacob.champion@enterprisedb.com>
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>
Content-Language: en-US
From: Fujii Masao <masao.fujii@oss.nttdata.com>
In-Reply-To: <CAAKRu_aV+B2yLpkcfh06tJV7XQPodjasxQ=XKh+MjD8ixkXwrA@mail.gmail.com>
Content-Type: text/plain; charset=UTF-8; format=flowed
Content-Transfer-Encoding: 8bit
Archived-At: <https://www.postgresql.org/message-id/65fe2d68-a214-40f0-80a8-56ca7323ad5c%40oss.nttdata.com>
Precedence: bulk


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