Re: Delays between "connection received" and "connection authenticated" because of localhost entries in hba

On Tue, 29 Oct 2024 at 23:43, Vijaykumar Jain <
vijaykumarjain(dot)github(at)gmail(dot)com> wrote:

>
>
> On Tue, 29 Oct 2024 at 22:00, Daniel Westermann (DWE) <
> daniel(dot)westermann(at)dbi-services(dot)com> wrote:
>
>> Delays between "connection received" and "connection authenticated"
>> because of localhost entries in hba
>>
>> Hi,
>>
>> we're facing a strange issue with delays between "connection received"
>> and "connection authenticated".
>>
>> # select version();
>> version
>>
>> -----------------------------------------------------------------------------------------------------------------------------------
>> PostgreSQL 15.6 (Ubuntu 15.6-1.pgdg22.04+1) on x86_64-pc-linux-gnu,
>> compiled by gcc (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0, 64-bit
>> (1 ligne)
>>
>> I know, this is not the latest minor version.
>>
>> # \! cat /etc/os-release | head -1
>> PRETTY_NAME="Ubuntu 22.04.4 LTS"
>>
>> What we see in the log is this (around 4 seconds delay):
>>
>> 2024-05-07 15:29:50.244 CEST [369909] LOG: connection received:
>> host=xx.xx.xx.100 port=48434
>> 2024-05-07 15:29:54.518 CEST [369909] LOG: connection authenticated:
>> identity="xxxxxx" method=md5 (/etc/postgresql/15/main/pg_hba.conf:121)
>>
>>
> Just before we get into os and name resolution stuff..
>
> 1) if the database usage is really heavy with schema churn and or heavy
> temp usage. can the catalog bloat result in slowless of pg_auth* objects
> resulting in slow authentication?
> a general check used to be checking the size of the catalog objects and
> if needed vacuum full in single user mode .... to speed up auth lookup.
>
> i tried with pg latest on ubuntu 22, but did not see any issues.
>
>
> So to simulate a similar issue, i understand once connected, it will look
> up pg_auth* objects cascading to other catalogs for resolution ...
> in one session:
> PGPASSWORD=1234 psql -h localhost -p 5432 -d postgres -U postgres -c
> 'select 1'
>
> in another session
>
> postgres(at)ubuntu:~$ cat /tmp/db1/postgresql.auto.conf
> # Do not edit this file manually!
> # It will be overwritten by the ALTER SYSTEM command.
> trace_locks = 'on'
> trace_lock_table = 1260
>
>
> postgres=# select 'pg_authid'::regclass::oid;
> oid
> ------
> 1260
> (1 row)
> postgres=*# lock table pg_authid in access exclusive mode;
> LOCK TABLE
> postgres=*# rollback;
> ROLLBACK
>
>
> i tried to trace which locks are held when a connection is established
> after auth.
>
> for example pg_authid , so i enable tracing on this object, and to mock
> the delay i try to lock the table in access exclusive mode ...
> note, this may not be the scenario, but i am trying to rule out pg related
> delay due to bloat or locking
>
>
> postgres(at)ubuntu:/tmp$ time PGPASSWORD=1234 psql -h localhost -p 5432 -d
> postgres -U postgres -c 'select 1'
> ?column?
> ----------
> 1
> (1 row)
>
>
> real 0m7.503s - -delay
> user 0m0.001s
> sys 0m0.005s
>
> postgres(at)ubuntu:/tmp$ #after rollback of pg_authid
>
>
> from the logs
> 2024-10-29 18:04:46.411 UTC [localhost(33424)] [62661] LOG: connection
> received: host=localhost port=33424
> 2024-10-29 18:04:53.906 UTC [localhost(33424)] [62661] LOG: connection
> authenticated: identity="postgres" method=md5 (/tmp/db1/pg_hba.conf:120)
>
>
> what i tried here was, delay auth but after connection established till
> lock held, which can be due to bloated catalog objects or long locks due to
> temp objects churn?
>
> still it does not explain how the order of pg_hba deals with the delay ?
>
> anyways, fyi to rule out :)
>
> --
> Thanks,
> Vijay
>
> Open to work
> Resume - Vijaykumar Jain <https://github.com/cabecada>
>

sorry, sharing again.