Establishing a local connection to PostgreSQL 9.6 takes seconds

From: Marcin Barczynski <mbarczynski(at)starfishstorage(dot)com>
To: pgsql-general(at)lists(dot)postgresql(dot)org
Subject: Establishing a local connection to PostgreSQL 9.6 takes seconds
Date: 2021-06-16 14:01:18
Message-ID: CAOhG4wdds=GsnrOK83Fgw2WZQaR7ziF6P5zb-eZ6xogfpAyhTw@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-general

In a heavily used production database prod, running a `psql prod` takes
seconds. Once the connection is established, performance of queries is
fine. There are ~2 new usually short-lived connections / second, and a
couple of long-running analytical queries. Connecting to other databases on
the same PostgreSQL server is fast.

Here is what I tried:

-bash-4.2$ date; psql prod -c "SELECT backend_start, xact_start,
query_start FROM pg_stat_activity WHERE pid = (SELECT pg_backend_pid());";
date
Wed Jun 16 09:01:51 EDT 2021
backend_start | xact_start |
query_start
-------------------------------+-------------------------------+-------------------------------
2021-06-16 09:01:51.596197-04 | 2021-06-16 09:01:57.979979-04 | 2021-06-16
09:01:57.979979-04
(1 row)

Wed Jun 16 09:01:57 EDT 2021

So the backend started quickly, but it took 6 seconds to start running the
query.
I used

ps --sort=start_time -elfy | grep "postgres prod .*startup" | head -n1 |
awk '{print $3}'

to identify the PID the most recent pg backend started by myself in startup
mode.
I straced PG backend after running psql:

$ sudo strace -tt -T -v -p $(ps --sort=start_time -elfy | grep "postgres
prod .*startup" | head -n1 | awk '{print $3}')
(...)
08:47:28.870917 read(6, "|\25\3\0\0|\v\335$!\1\0\364\0\20\1\0 \4
\374%\4\6p\237\30\1\340\236\30\1"..., 8192) = 8192 <0.000010>
08:47:28.870951 read(6, "|\25\3\0(at)\274\202\262\254\230\1\0\364\0\20\1\0 \4
\0&\4\6p\237\30\1\340\236\30\1"..., 8192) = 8192 <0.000010>
08:47:28.870986 read(6, "|\25\3\0\220\f\270\266\24\t\1\0\364\0\20\1\0 \4
\5&\4\6p\237\30\1\340\236\30\1"..., 8192) = 8192 <0.000010>
08:47:28.871021 read(6, "|\25\3\0008%\200\262r%\1\0\364\0\20\1\0 \4
\4&\4\6p\237\30\1\340\236\30\1"..., 8192) = 8192 <0.000011>
08:47:28.871056 semop(41779221, [{8, 1, 0}], 1) = 0 <0.000010>
08:47:28.871088 read(6, "|\25\3\0\220[\202\262\241\230\1\0\364\0\20\1\0 \4
\6&\4\6p\237\30\1\340\236\30\1"..., 8192) = 8192 <0.000010>
08:47:28.871124 read(6, "|\25\3\0\350\247\200\262\32^\1\0\364\0\20\1\0 \4
\1&\4\6p\237\30\1\340\236\30\1"..., 8192) = 8192 <0.000010>
08:47:28.871158 read(6, "|\25\3\0P\373\262\266D\262\1\0\364\0\20\1\0 \4
\373%\4\6p\237\30\1\340\236\30\1"..., 8192) = 8192 <0.000010>
08:47:28.871192 read(6, "|\25\3\0\360\240\201\262\345\206\1\0\364\0\20\1\0
\4 \3&\4\6p\237\30\1\340\236\30\1"..., 8192) = 8192 <0.000010>
08:47:28.871227 read(6, "|\25\3\0p\372\262\266\0h\1\0\364\0\20\1\0 \4
\2&\4\6p\237\30\1\340\236\30\1"..., 8192) = 8192 <0.000010>
08:47:28.871262 read(6, "|\25\3\0(at)\370\262\266\313\267\1\0\364\0\20\1\0 \4
\7&\4\6p\237\30\1\340\236\30\1"..., 8192) = 8192 <0.000011>
(...)

then stopped strace and ran:

$ sudo lsof -p $(ps --sort=start_time -elfy | grep "postgres prod
.*startup" | head -n1 | awk '{print $3}')
(...)
postmaste 4722 postgres 6u REG 8,1 1073741824
369860117 /opt/prod/pg/9.6/base/18370/1108887031
(...)

It's always /opt/prod/pg/9.6/base/18370/1108887031. Unfortunately, no trace
of it in pg_class:

prod=# SELECT relname FROM pg_class WHERE oid = 1108887031;
relname
---------
(0 rows)
prod=# SELECT relname FROM pg_class WHERE relfilenode = 1108887031;
relname
---------
(0 rows)

What does pg backend do on startup?
I would be thankful for suggestions on how to troubleshoot it.

Versions:

PostgreSQL 9.6.21 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5
20150623 (Red Hat 4.8.5-44), 64-bit
Linux 3.10.0-1062.el7.x86_64 #1 SMP Wed Aug 7 18:08:02 UTC 2019 x86_64
x86_64 x86_64 GNU/Linux

--
Thanks,
Marcin

Responses

Browse pgsql-general by date

  From Date Subject
Next Message Tom Lane 2021-06-16 14:10:11 Re: Establishing a local connection to PostgreSQL 9.6 takes seconds
Previous Message Peter J. Holzer 2021-06-16 11:03:10 Re: clear cache in postgresql