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

[Vijaykumar Jain <vijaykumarjain.github@xxxxxxxxx>]

On Tue, 29 Oct 2024 at 23:43, Vijaykumar Jain <vijaykumarjain.github@xxxxxxxxx> wrote:

On Tue, 29 Oct 2024 at 22:00, Daniel Westermann (DWE) <daniel.westermann@xxxxxxxxxxxxxxxx> 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@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@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@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

sorry,  sharing again.