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
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 |