Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1t5qxW-0090sW-00 for pgsql-general@arkaria.postgresql.org; Tue, 29 Oct 2024 18:28:50 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.94.2) (envelope-from ) id 1t5qxU-001pPY-Ap for pgsql-general@arkaria.postgresql.org; Tue, 29 Oct 2024 18:28:48 +0000 Received: from makus.postgresql.org ([2001:4800:3e1:1::229]) by malur.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1t5qxT-001pPP-R4 for pgsql-general@lists.postgresql.org; Tue, 29 Oct 2024 18:28:48 +0000 Received: from mail-lf1-x142.google.com ([2a00:1450:4864:20::142]) by makus.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 (Exim 4.94.2) (envelope-from ) id 1t5qxR-003Ui9-0X for pgsql-general@postgresql.org; Tue, 29 Oct 2024 18:28:46 +0000 Received: by mail-lf1-x142.google.com with SMTP id 2adb3069b0e04-539f0f9ee49so6262096e87.1 for ; Tue, 29 Oct 2024 11:28:44 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20230601; t=1730226523; x=1730831323; darn=postgresql.org; h=to:subject:message-id:date:from:in-reply-to:references:mime-version :from:to:cc:subject:date:message-id:reply-to; bh=2e64glPysty4b+0rhtbkjzTuXEcnpUF75jpab54UPL8=; b=GgyVqB8Jm/5C+mTU0WtdDB6qQb62LS7mWbR6NATgQ+GOP8Oqmk3R8lVx9kzM+iApvY sGUG0UHwOs3qd9bXc5XiMUKZFXNuzjdPWfRuwo1aWIgF43AVOQphnd2Lz7/IXS52AT90 xWW/LnRiRvsxEAC6GwC5J09UdMfxQo6fk1fAzd7yCXSBZDJkbUa0bBvd+w1s3QljEK8m j2fc9rFuektwSetGiHfp9w8goy16tY6SwX2NeWO63B7kwAcuXwanRehYoF6MjGcetFPy mtnR75xz9pQZ9slY2j4OwnR7qnhXiXkkZaM0mdFw0cijn94X78IY60lCUXxxBRvOnK2N qeiw== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1730226523; x=1730831323; h=to:subject:message-id:date:from:in-reply-to:references:mime-version :x-gm-message-state:from:to:cc:subject:date:message-id:reply-to; bh=2e64glPysty4b+0rhtbkjzTuXEcnpUF75jpab54UPL8=; b=OMGHqUg1dv/K8YCcYlBPRXEbobkkV4I/W/vAyOfMZ8BHvd4BV4mVY2Gr++B5E5TaTA jMH6YedOLvtVZOJ2K8SkRDui3iUB6m06R63HF7WkJoG+SpgafwqpBcPnkOUJoKuMH/7p 60DqzPXkspc6Bzi/XBH145R92w83CgIP/LJYVcSGEaLw03K290iDFNCiJXVa0Op56Phz JCj4kgnVWOBQr0R+Zl9D4Q44yhqgj3qfEnQW1b2gAKsgp1uJyYjCd5I7KfAVgr3tbjnY +sMZq53YGXJeOHtzhdVrIYjQTH2/RIyHQZ81aayUtzSzrAwVNTLLhZuov0vs4b1NDqx9 erOA== X-Forwarded-Encrypted: i=1; AJvYcCXCxWFVPGGBcSctQQj2/BFsKyYXYqXVJQipB0jrNr7ShO0lYRhmjDVAKIKr+XNZu8kdlUeeAXeFXRaGd1Ip@postgresql.org X-Gm-Message-State: AOJu0YyEBBtVlxTL9o64/aofLg4S71vwuAlYR82vloWj+k/gh4XvTXMV YIrOxzJQK+Vo/R2iFc+F7svPrTMC99T9c24anYI1TwC0F2pag3KbN0ikae/CJx4gyaHA/TQeikO /81NrdLozsncFwUCTPc18uw33I433PMZM X-Google-Smtp-Source: AGHT+IFucOKVRt8zd7/rGGk8q8ZhqXCiVQy4f782EjY0cv6k9s+8CxUcuE6KvjxkL7JQ+1WLXasMXvLWEkm21GTTRHM= X-Received: by 2002:a05:6512:3ba0:b0:52c:e17c:3741 with SMTP id 2adb3069b0e04-53b348b7c07mr5868433e87.5.1730226522894; Tue, 29 Oct 2024 11:28:42 -0700 (PDT) MIME-Version: 1.0 References: In-Reply-To: From: Vijaykumar Jain Date: Tue, 29 Oct 2024 23:58:30 +0530 Message-ID: Subject: Re: Delays between "connection received" and "connection authenticated" because of localhost entries in hba To: "Daniel Westermann (DWE)" , pgsql-general Content-Type: multipart/alternative; boundary="0000000000004740a00625a1c11c" List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk --0000000000004740a00625a1c11c Content-Type: text/plain; charset="UTF-8" On Tue, 29 Oct 2024 at 23:43, Vijaykumar Jain < vijaykumarjain.github@gmail.com> wrote: > > > On Tue, 29 Oct 2024 at 22:00, Daniel Westermann (DWE) < > daniel.westermann@dbi-services.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@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. --0000000000004740a00625a1c11c Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable

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


On Tue, 29 Oct 2024 at 22:00, Daniel Westermann = (DWE) <daniel.westermann@dbi-services.com> wrote:
Delays between "connection re= ceived" and "connection authenticated" because of localhost = entries in hba

Hi,

we're facing a strange issue with delays between "connection recei= ved" and "connection authenticated".

# select version();
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 versi= on
---------------------------------------------------------------------------= --------------------------------------------------------
=C2=A0PostgreSQL 15.6 (Ubuntu 15.6-1.pgdg22.04+1) on x86_64-pc-linux-gnu, c= ompiled 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=3D"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:=C2=A0 connection received: host= =3Dxx.xx.xx.100 port=3D48434
2024-05-07 15:29:54.518 CEST [369909] LOG:=C2=A0 connection authenticated: = identity=3D"xxxxxx" method=3Dmd5 (/etc/postgresql/15/main/pg_hba.= conf:121)


Just before we get into o= s and name resolution stuff..

1) if the database u= sage is really heavy with schema churn=C2=A0 and or heavy temp usage. can t= he catalog bloat result in slowless of pg_auth* objects resulting in slow a= uthentication?
=C2=A0a 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.=C2=A0


=
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:
=C2=A0PGPASSWORD=3D1234 psql -h local= host -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 manua= lly!
# It will be overwritten by the ALTER SYSTEM command.
<= div>trace_locks =3D 'on'
trace_lock_table =3D 1260
<= /div>


postgres=3D# select 'pg_au= thid'::regclass::oid;
=C2=A0oid
------
= =C2=A01260
(1 row)
postgres=3D*# lock table = pg_authid in access exclusive mode;
LOCK TABLE
postgres= =3D*# rollback;
ROLLBACK


i tried to trace which locks are held when a connection is establishe= d 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 ac= cess exclusive mode ...
note, this may not be the scenario, but i= am trying to rule out pg related delay due to bloat or locking=C2=A0
=


postgres@ubuntu:/tmp$ time PGPASSWO= RD=3D1234 psql -h localhost -p 5432 -d postgres -U postgres -c 'select = 1'
=C2=A0?column?
----------
=C2=A0 =C2= =A0 =C2=A0 =C2=A0 1
(1 row)


real=C2=A0 =C2=A0 0m7.503s=C2=A0 - -delay
user=C2=A0 =C2=A0 0m= 0.001s
sys=C2=A0 =C2=A0 =C2=A00m0.005s

p= ostgres@ubuntu:/tmp$ #after rollback of pg_authid


from the=C2=A0logs
2024-10-29 18:04:46.= 411 UTC [localhost(33424)] [62661] LOG:=C2=A0 connection received: host=3Dl= ocalhost port=3D33424
2024-10-29 18:04:53.906 UTC [localhost(3342= 4)] [62661] LOG:=C2=A0 connection authenticated: identity=3D"postgres&= quot; method=3Dmd5 (/tmp/db1/pg_hba.conf:120)


what i tried here was, delay auth but after connection est= ablished till lock held, which can be due to bloated catalog objects or lon= g locks due to temp objects churn?

still it does n= ot explain how the order of pg_hba=C2=A0deals with the delay ?=C2=A0
<= div>
=C2=A0anyways, fyi to rule out :)

--
Thanks,
Vijay

<= /div>
Open to work
Resume -=C2=A0Vijaykumar Jain


sorry,=C2=A0 shari= ng again.

--0000000000004740a00625a1c11c--