Re: Log connection establishment timings

On 2025/03/01 7:52, Melanie Plageman wrote:
> On Fri, Feb 28, 2025 at 12:54 AM Bertrand Drouvot
> <bertranddrouvot(dot)pg(at)gmail(dot)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.

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

Regards,

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