Max connections reached without max connections reached
Hi,
This is a bit of an odd one - I'm on PostgreSQL 11.9 with a single
streaming replica.
The system handles a lot of connections - we have a max_connections of 600.
Most are long lived JDBC, but there are a lot of ETL / ad-hoc jobs etc.
Connections normally sit at 300ish, with 70 active at the most. The
machines have 32 CPU cores . PgBouncer is sadly not an option hereas we are
using many long lived connections which make use of prepared statements.
Sometimes a strange condition occurs. The number of connections is well
under 600 (and dropping), but new connections are not being allowed into
the database, I can see this message in the logs:
(0:53300)FATAL: remaining connection slots are reserved for
non-replication superuser connections
From ps I can see a lot of processes like this:
postgres: accessor monitoring 10.10.7.54[41655] startup
The number of these grows, and no new connections are allowed in. These
startup connections do not appear in pg_stat_activity so I can't find what
they are waiting on.
Removing some long lived connections sometimes appears to help clear the
startup processes and return the system to normal - but I have not been
able to find a correlation. It's more blind luck at the moment.
Any pointers on where I could start prodding?
Cheers,
James
--
The contents of this email are confidential and may be subject to legal or
professional privilege and copyright. No representation is made that this
email is free of viruses or other defects. If you have received this
communication in error, you may not copy or distribute any part of it or
otherwise disclose its contents to anyone. Please advise the sender of your
incorrect receipt of this correspondence.
James Sewell <james.sewell@jirotech.com> writes:
The system handles a lot of connections - we have a max_connections of 600.
Most are long lived JDBC, but there are a lot of ETL / ad-hoc jobs etc.
Connections normally sit at 300ish, with 70 active at the most. The
machines have 32 CPU cores . PgBouncer is sadly not an option hereas we are
using many long lived connections which make use of prepared statements.
Sometimes a strange condition occurs. The number of connections is well
under 600 (and dropping), but new connections are not being allowed into
the database, I can see this message in the logs:
(0:53300)FATAL: remaining connection slots are reserved for
non-replication superuser connections
What are you looking at to claim the number of connections is under 600?
Maybe there's some disconnect between what you're measuring and what the
database thinks.
A different line of thought is that ProcArray slots can be consumed by
things that aren't client connection processes, in particular
(1) parallel-query workers
(2) autovacuum workers
Looking into pg_stat_activity when you see this issue might help
clarify that.
regards, tom lane
What are you looking at to claim the number of connections is under 600?
Maybe there's some disconnect between what you're measuring and what the
database thinks.A different line of thought is that ProcArray slots can be consumed by
things that aren't client connection processes, in particular
(1) parallel-query workers
(2) autovacuum workers
Looking into pg_stat_activity when you see this issue might help
clarify that.
Sorry, I could have been clearer - pg_stat_activity is what I'm looking at
- I'm recording connection info from here every 15 seconds (from a
superuser account so I don't get locked out). It never peaks above 300 (in
fact when the incident happens no new connections can come in so it falls
to around 100) - yet I'm seeing the log lines claim that I'm still hitting
597 (600 - 3 reserved).
If I measure from `ps -ef | grep postgres` and look at the connections
then I can see that with the startup connections I am hitting this limit.
So client processes which are listed to the OS as "startup" ARE counted
towards the 597 connections, but are NOT reported in pg_stat_activity
James
--
The contents of this email are confidential and may be subject to legal or
professional privilege and copyright. No representation is made that this
email is free of viruses or other defects. If you have received this
communication in error, you may not copy or distribute any part of it or
otherwise disclose its contents to anyone. Please advise the sender of your
incorrect receipt of this correspondence.
On 11/23/21 14:56, James Sewell wrote:
Sorry, I could have been clearer - pg_stat_activity is what I'm looking
at - I'm recording connection info from here every 15 seconds (from a
superuser account so I don't get locked out). It never peaks above 300
(in fact when the incident happens no new connections can come in so it
falls to around 100) - yet I'm seeing the log lines claim that I'm still
hitting 597 (600 - 3 reserved).
What is the query you are using against pg_stat_activity?
James
--
Adrian Klaver
adrian.klaver@aklaver.com
James Sewell <james.sewell@jirotech.com> writes:
If I measure from `ps -ef | grep postgres` and look at the connections
then I can see that with the startup connections I am hitting this limit.
So client processes which are listed to the OS as "startup" ARE counted
towards the 597 connections, but are NOT reported in pg_stat_activity
So I guess the question becomes why are they spending so much time in
the startup state. That should take mere milliseconds, unless the
clients are being slow to handle the authentication exchange?
I'm also wondering a bit about whether they're being blocked on a lock,
eg. due to something taking an exclusive lock on pg_authid or pg_database.
pg_locks might be interesting to check.
regards, tom lane
Sorry, I could have been clearer - pg_stat_activity is what I'm looking
at - I'm recording connection info from here every 15 seconds (from a
superuser account so I don't get locked out). It never peaks above 300
(in fact when the incident happens no new connections can come in so it
falls to around 100) - yet I'm seeing the log lines claim that I'm still
hitting 597 (600 - 3 reserved).What is the query you are using against pg_stat_activity?
For general counts ad-hoc we just use:
SELECT count(*) FROM pg_stat_activity
The monitoring system runs:
SELECT CASE WHEN usename IS NOT NULL THEN usename ELSE 'SYSTEM' END as
role,
datname AS database,
state,
wait_event,
count(*) AS connection
FROM pg_stat_activity
GROUP BY 1,2,3,4
--
The contents of this email are confidential and may be subject to legal or
professional privilege and copyright. No representation is made that this
email is free of viruses or other defects. If you have received this
communication in error, you may not copy or distribute any part of it or
otherwise disclose its contents to anyone. Please advise the sender of your
incorrect receipt of this correspondence.
So I guess the question becomes why are they spending so much time in
the startup state. That should take mere milliseconds, unless the
clients are being slow to handle the authentication exchange?I'm also wondering a bit about whether they're being blocked on a lock,
eg. due to something taking an exclusive lock on pg_authid or pg_database.
pg_locks might be interesting to check.
It's v odd as it happens *sometimes* - having said that it's happening
right this moment:
[enterprisedb@oprpgs001 edb-as-11]$ ps -ef|grep postgres: | wc -l
517
[enterprisedb@oprpgs001 ~]$ ps -ef|grep postgres: | grep -i start | wc -l
480
postgres=# select count(*) from pg_stat_activity;
count
-------
97
(1 row)
postgres=# select * from pg_locks where not granted;
locktype | database | relation | page | tuple | virtualxid | transactionid
| classid | objid | objsubid | virtualtransaction | pid | mode | granted |
fastpath
----------+----------+----------+------+-------+------------+---------------+---------+-------+----------+--------------------+-----+------+---------+----------
(0 rows)
Logs are showing a stream of:
2021-11-24 10:50:58 AEDT [869]: [1-1]
user=u_rundeck_rw,db=rundeck_cluster,client=10.154.19.23
10.154.19.23(57122) (0:53300)FATAL: remaining connection slots are
reserved for non-replication superuser connections
2021-11-24 10:50:58 AEDT [870]: [1-1]
user=u_rundeck_rw,db=rundeck_cluster,client=10.154.19.23
10.154.19.23(57124) (0:53300)FATAL: remaining connection slots are
reserved for non-replication superuser connections
2021-11-24 10:50:58 AEDT [871]: [1-1]
user=u_rundeck_rw,db=rundeck_cluster,client=10.154.19.23
10.154.19.23(57126) (0:53300)FATAL: remaining connection slots are
reserved for non-replication superuser connections
James
--
The contents of this email are confidential and may be subject to legal or
professional privilege and copyright. No representation is made that this
email is free of viruses or other defects. If you have received this
communication in error, you may not copy or distribute any part of it or
otherwise disclose its contents to anyone. Please advise the sender of your
incorrect receipt of this correspondence.
On 11/23/21 15:53, James Sewell wrote:
It's v odd as it happens *sometimes* - having said that it's happening
right this moment:[enterprisedb@oprpgs001 edb-as-11]$ ps -ef|grep postgres: | wc -l
517[enterprisedb@oprpgs001 ~]$ ps -ef|grep postgres: | grep -i start | wc -l
480
The enterprisedb is one of their customized versions?
rundeck_cluster below refers to https://digital.ai/technology/rundeck?
postgres=# select count(*) from pg_stat_activity;
count
-------
97
(1 row)postgres=# select * from pg_locks where not granted;
locktype | database | relation | page | tuple | virtualxid |
transactionid | classid | objid | objsubid | virtualtransaction | pid |
mode | granted | fastpath
----------+----------+----------+------+-------+------------+---------------+---------+-------+----------+--------------------+-----+------+---------+----------
(0 rows)
Logs are showing a stream of:2021-11-24 10:50:58 AEDT [869]: [1-1]
user=u_rundeck_rw,db=rundeck_cluster,client=10.154.19.23
10.154.19.23(57122) (0:53300)FATAL: remaining connection slots are
reserved for non-replication superuser connections
2021-11-24 10:50:58 AEDT [870]: [1-1]
user=u_rundeck_rw,db=rundeck_cluster,client=10.154.19.23
10.154.19.23(57124) (0:53300)FATAL: remaining connection slots are
reserved for non-replication superuser connections
2021-11-24 10:50:58 AEDT [871]: [1-1]
user=u_rundeck_rw,db=rundeck_cluster,client=10.154.19.23
10.154.19.23(57126) (0:53300)FATAL: remaining connection slots are
reserved for non-replication superuser connectionsJames
--
Adrian Klaver
adrian.klaver@aklaver.com
The enterprisedb is one of their customized versions?
rundeck_cluster below refers to https://digital.ai/technology/rundeck?
re: EnterpriseDB yes it is - I'm having this same discussion with them in
parallel
re: rundeck, yes - but this is only one of many things connecting. it's not
doing anything special.
--
The contents of this email are confidential and may be subject to legal or
professional privilege and copyright. No representation is made that this
email is free of viruses or other defects. If you have received this
communication in error, you may not copy or distribute any part of it or
otherwise disclose its contents to anyone. Please advise the sender of your
incorrect receipt of this correspondence.
On 11/23/21 16:23, James Sewell wrote:
The enterprisedb is one of their customized versions?
rundeck_cluster below refers to
https://digital.ai/technology/rundeck
<https://digital.ai/technology/rundeck>?re: EnterpriseDB yes it is - I'm having this same discussion with them
in parallel
What version of theirs?
re: rundeck, yes - but this is only one of many things connecting. it's
not doing anything special.
Except sending a stream of connections to the server.
Any idea what they are doing?
--
Adrian Klaver
adrian.klaver@aklaver.com
re: EnterpriseDB yes it is - I'm having this same discussion with them
in parallelWhat version of theirs?
PostgreSQL 11.9 (EnterpriseDB Advanced Server 11.9.18) on
x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5 20150623 (Red Hat
4.8.5-36), 64-bit
re: rundeck, yes - but this is only one of many things connecting. it's
not doing anything special.Except sending a stream of connections to the server.
Any idea what they are doing?
It's used to trigger ETL jobs. There are other bigger consumers of
connections - the issue isn't the stream of jobs, that works fine under
normal operation. The issue is that when jobs stay in "startup" and don't
enter pg_stat_activity the system spirals downwards and no new connections
are allowed.
James
--
The contents of this email are confidential and may be subject to legal or
professional privilege and copyright. No representation is made that this
email is free of viruses or other defects. If you have received this
communication in error, you may not copy or distribute any part of it or
otherwise disclose its contents to anyone. Please advise the sender of your
incorrect receipt of this correspondence.
On 11/23/21 16:58, James Sewell wrote:
re: EnterpriseDB yes it is - I'm having this same discussion with
them
in parallel
What version of theirs?
PostgreSQL 11.9 (EnterpriseDB Advanced Server 11.9.18) on
x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5 20150623 (Red Hat
4.8.5-36), 64-bitre: rundeck, yes - but this is only one of many things
connecting. it's
not doing anything special.
Except sending a stream of connections to the server.
Any idea what they are doing?
It's used to trigger ETL jobs. There are other bigger consumers of
connections - the issue isn't the stream of jobs, that works fine under
normal operation. The issue is that when jobs stay in "startup" and
don't enter pg_stat_activity the system spirals downwards and no new
connections are allowed.
Is there a correlation to these ETL jobs or the other consumers?
If so what are the consumers trying to do at that time?
James
--
Adrian Klaver
adrian.klaver@aklaver.com
It's used to trigger ETL jobs. There are other bigger consumers of
connections - the issue isn't the stream of jobs, that works fine under
normal operation. The issue is that when jobs stay in "startup" and
don't enter pg_stat_activity the system spirals downwards and no new
connections are allowed.Is there a correlation to these ETL jobs or the other consumers?
If so what are the consumers trying to do at that time?
Not really no - it seems to be pretty randomly timed.
--
The contents of this email are confidential and may be subject to legal or
professional privilege and copyright. No representation is made that this
email is free of viruses or other defects. If you have received this
communication in error, you may not copy or distribute any part of it or
otherwise disclose its contents to anyone. Please advise the sender of your
incorrect receipt of this correspondence.
James Sewell <james.sewell@jirotech.com> writes:
I'm also wondering a bit about whether they're being blocked on a lock,
eg. due to something taking an exclusive lock on pg_authid or pg_database.
pg_locks might be interesting to check.
postgres=# select * from pg_locks where not granted;
The hypothesis I'm thinking of is that incoming sessions are being blocked
somewhere before they can acquire a ProcArray entry; if so, they'd not
show up in either pg_stat_activity or pg_locks. What we have to look for
then is evidence of somebody holding a strong lock on a shared relation.
Try "select * from pg_locks where locktype = 'relation' and database = 0".
regards, tom lane
The hypothesis I'm thinking of is that incoming sessions are being blocked
somewhere before they can acquire a ProcArray entry; if so, they'd not
show up in either pg_stat_activity or pg_locks. What we have to look for
then is evidence of somebody holding a strong lock on a shared relation.
Try "select * from pg_locks where locktype = 'relation' and database = 0".
That doesn't show anything when the issue is happening.
Strace shows the startup processes looping like so:
13:51:15.510850 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358,
tv_nsec=733559666}) = 0
13:51:15.511254 futex(0x7ee891405238, FUTEX_WAKE, 1) = 1
13:51:15.511422 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358,
tv_nsec=734037545}) = 0
13:51:15.511690 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.520470 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358,
tv_nsec=743136450}) = 0
13:51:15.520772 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358,
tv_nsec=743376746}) = 0
13:51:15.521005 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.539309 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358,
tv_nsec=761920081}) = 0
13:51:15.539508 futex(0x7ee891406bb8, FUTEX_WAKE, 1) = 1
13:51:15.539690 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358,
tv_nsec=762298276}) = 0
13:51:15.539882 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.547311 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358,
tv_nsec=769929341}) = 0
13:51:15.547757 futex(0x7ee89140a738, FUTEX_WAKE, 1) = 1
13:51:15.547931 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358,
tv_nsec=770524120}) = 0
13:51:15.548089 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.551482 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = -1 EAGAIN
(Resource temporarily unavailable)
13:51:15.551950 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.593631 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = -1 EAGAIN
(Resource temporarily unavailable)
13:51:15.593807 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.626167 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.627590 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358,
tv_nsec=850204434}) = 0
13:51:15.627817 futex(0x7ee8914033b8, FUTEX_WAKE, 1) = 1
13:51:15.627987 open("pg_subtrans/A100", O_RDWR) = 16
13:51:15.628270 lseek(16, 131072, SEEK_SET) = 131072
13:51:15.628461 read(16,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
8192) = 8192
13:51:15.628677 close(16) = 0
13:51:15.628911 open("pg_subtrans/A0E1", O_RDWR) = 16
13:51:15.629132 lseek(16, 122880, SEEK_SET) = 122880
13:51:15.629309 read(16,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
8192) = 8192
13:51:15.629503 close(16) = 0
13:51:15.629685 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358,
tv_nsec=852272645}) = 0
13:51:15.629863 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.656694 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358,
tv_nsec=879314944}) = 0
13:51:15.656923 futex(0x7ee8914125b8, FUTEX_WAKE, 1) = 1
13:51:15.657129 open("pg_subtrans/A0EE", O_RDWR) = 16
13:51:15.657385 lseek(16, 73728, SEEK_SET) = 73728
13:51:15.657638 read(16,
"\0\0\0\0\0H\356\240\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\5H\356\240\0\0\0\0"...,
8192) = 8192
13:51:15.657907 close(16) = 0
13:51:15.658141 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358,
tv_nsec=880753952}) = 0
13:51:15.658346 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.689705 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358,
tv_nsec=912331058}) = 0
13:51:15.689950 futex(0x7ee89140a0b8, FUTEX_WAKE, 1) = 1
13:51:15.690182 futex(0x7ee8914118b8, FUTEX_WAKE, 1) = 1
13:51:15.690420 open("pg_subtrans/A0EE", O_RDWR) = 16
13:51:15.690742 lseek(16, 73728, SEEK_SET) = 73728
13:51:15.691037 read(16,
"\0\0\0\0\0H\356\240\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\5H\356\240\0\0\0\0"...,
8192) = 8192
13:51:15.691303 close(16) = 0
13:51:15.691582 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358,
tv_nsec=914202777}) = 0
13:51:15.691837 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.713319 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.716423 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358,
tv_nsec=939067321}) = 0
13:51:15.716737 futex(0x7ee89140a0b8, FUTEX_WAKE, 1) = 1
13:51:15.717010 futex(0x7ee89140f3b8, FUTEX_WAKE, 1) = 1
13:51:15.717286 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358,
tv_nsec=939899218}) = 0
13:51:15.717578 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.722270 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.746391 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358,
tv_nsec=969020657}) = 0
13:51:15.746664 futex(0x7ee89140fa38, FUTEX_WAKE, 1) = 1
13:51:15.746877 open("pg_subtrans/A0EE", O_RDWR) = 16
While gdb shows similar to:
24 ^[[?1034h(gdb) bt
23 #0 0x00007f18fb9deb3b in do_futex_wait.constprop.1 () from
/lib64/libpthread.so.0
22 #1 0x00007f18fb9debcf in __new_sem_wait_slow.constprop.0 () from
/lib64/libpthread.so.0
21 #2 0x00007f18fb9dec6b in sem_wait@@GLIBC_2.2.5 () from
/lib64/libpthread.so.0
20 #3 0x000000000071c482 in PGSemaphoreLock ()
19 #4 0x000000000079078c in LWLockAcquire ()
18 #5 0x00000000004fa9ae in SimpleLruWaitIO.isra.1 ()
17 #6 0x00000000004fb2a4 in SimpleLruReadPage ()
16 #7 0x00000000004fbc07 in SubTransGetParent ()
15 #8 0x00000000004fbc57 in SubTransGetTopmostTransaction ()
14 #9 0x00000000008f65a7 in XidInMVCCSnapshot ()
13 #10 0x00000000008f662e in HeapTupleSatisfiesMVCC ()
12 #11 0x00000000004c436e in heapgetpage ()
11 #12 0x00000000004c58e4 in heap_getnext ()
10 #13 0x00000000008ab8b5 in ScanPgRelation ()
9 #14 0x00000000008ae124 in RelationBuildDesc ()
8 #15 0x00000000008b010e in load_critical_index ()
7 #16 0x00000000008b39ac in RelationCacheInitializePhase3 ()
6 #17 0x00000000008cbd56 in InitPostgres ()
5 #18 0x00000000007a1cfe in PostgresMain ()
4 #19 0x000000000048a9c0 in ServerLoop ()
3 #20 0x000000000072f11e in PostmasterMain ()
2 #21 0x000000000048b854 in main ()
Does that shed any light?
- James
--
The contents of this email are confidential and may be subject to legal or
professional privilege and copyright. No representation is made that this
email is free of viruses or other defects. If you have received this
communication in error, you may not copy or distribute any part of it or
otherwise disclose its contents to anyone. Please advise the sender of your
incorrect receipt of this correspondence.
On Thu, Nov 25, 2021 at 8:58 AM James Sewell <james.sewell@jirotech.com> wrote:
The hypothesis I'm thinking of is that incoming sessions are being blocked
somewhere before they can acquire a ProcArray entry; if so, they'd not
show up in either pg_stat_activity or pg_locks. What we have to look for
then is evidence of somebody holding a strong lock on a shared relation.
Try "select * from pg_locks where locktype = 'relation' and database = 0".That doesn't show anything when the issue is happening.
Strace shows the startup processes looping like so:
13:51:15.510850 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=733559666}) = 0
13:51:15.511254 futex(0x7ee891405238, FUTEX_WAKE, 1) = 1
13:51:15.511422 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=734037545}) = 0
13:51:15.511690 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.520470 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=743136450}) = 0
13:51:15.520772 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=743376746}) = 0
13:51:15.521005 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.539309 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=761920081}) = 0
13:51:15.539508 futex(0x7ee891406bb8, FUTEX_WAKE, 1) = 1
13:51:15.539690 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=762298276}) = 0
13:51:15.539882 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.547311 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=769929341}) = 0
13:51:15.547757 futex(0x7ee89140a738, FUTEX_WAKE, 1) = 1
13:51:15.547931 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=770524120}) = 0
13:51:15.548089 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.551482 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = -1 EAGAIN (Resource temporarily unavailable)
13:51:15.551950 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.593631 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = -1 EAGAIN (Resource temporarily unavailable)
13:51:15.593807 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.626167 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.627590 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=850204434}) = 0
13:51:15.627817 futex(0x7ee8914033b8, FUTEX_WAKE, 1) = 1
13:51:15.627987 open("pg_subtrans/A100", O_RDWR) = 16
13:51:15.628270 lseek(16, 131072, SEEK_SET) = 131072
13:51:15.628461 read(16, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = 8192
13:51:15.628677 close(16) = 0
13:51:15.628911 open("pg_subtrans/A0E1", O_RDWR) = 16
13:51:15.629132 lseek(16, 122880, SEEK_SET) = 122880
13:51:15.629309 read(16, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = 8192
13:51:15.629503 close(16) = 0
13:51:15.629685 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=852272645}) = 0
13:51:15.629863 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.656694 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=879314944}) = 0
13:51:15.656923 futex(0x7ee8914125b8, FUTEX_WAKE, 1) = 1
13:51:15.657129 open("pg_subtrans/A0EE", O_RDWR) = 16
13:51:15.657385 lseek(16, 73728, SEEK_SET) = 73728
13:51:15.657638 read(16, "\0\0\0\0\0H\356\240\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\5H\356\240\0\0\0\0"..., 8192) = 8192
13:51:15.657907 close(16) = 0
13:51:15.658141 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=880753952}) = 0
13:51:15.658346 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.689705 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=912331058}) = 0
13:51:15.689950 futex(0x7ee89140a0b8, FUTEX_WAKE, 1) = 1
13:51:15.690182 futex(0x7ee8914118b8, FUTEX_WAKE, 1) = 1
13:51:15.690420 open("pg_subtrans/A0EE", O_RDWR) = 16
13:51:15.690742 lseek(16, 73728, SEEK_SET) = 73728
13:51:15.691037 read(16, "\0\0\0\0\0H\356\240\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\5H\356\240\0\0\0\0"..., 8192) = 8192
13:51:15.691303 close(16) = 0
13:51:15.691582 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=914202777}) = 0
13:51:15.691837 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.713319 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.716423 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=939067321}) = 0
13:51:15.716737 futex(0x7ee89140a0b8, FUTEX_WAKE, 1) = 1
13:51:15.717010 futex(0x7ee89140f3b8, FUTEX_WAKE, 1) = 1
13:51:15.717286 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=939899218}) = 0
13:51:15.717578 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.722270 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.746391 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=969020657}) = 0
13:51:15.746664 futex(0x7ee89140fa38, FUTEX_WAKE, 1) = 1
13:51:15.746877 open("pg_subtrans/A0EE", O_RDWR) = 16While gdb shows similar to:
24 ^[[?1034h(gdb) bt
23 #0 0x00007f18fb9deb3b in do_futex_wait.constprop.1 () from /lib64/libpthread.so.0
22 #1 0x00007f18fb9debcf in __new_sem_wait_slow.constprop.0 () from /lib64/libpthread.so.0
21 #2 0x00007f18fb9dec6b in sem_wait@@GLIBC_2.2.5 () from /lib64/libpthread.so.0
20 #3 0x000000000071c482 in PGSemaphoreLock ()
19 #4 0x000000000079078c in LWLockAcquire ()
18 #5 0x00000000004fa9ae in SimpleLruWaitIO.isra.1 ()
17 #6 0x00000000004fb2a4 in SimpleLruReadPage ()
16 #7 0x00000000004fbc07 in SubTransGetParent ()
15 #8 0x00000000004fbc57 in SubTransGetTopmostTransaction ()
14 #9 0x00000000008f65a7 in XidInMVCCSnapshot ()
13 #10 0x00000000008f662e in HeapTupleSatisfiesMVCC ()
12 #11 0x00000000004c436e in heapgetpage ()
11 #12 0x00000000004c58e4 in heap_getnext ()
10 #13 0x00000000008ab8b5 in ScanPgRelation ()
9 #14 0x00000000008ae124 in RelationBuildDesc ()
8 #15 0x00000000008b010e in load_critical_index ()
7 #16 0x00000000008b39ac in RelationCacheInitializePhase3 ()
6 #17 0x00000000008cbd56 in InitPostgres ()
5 #18 0x00000000007a1cfe in PostgresMain ()
4 #19 0x000000000048a9c0 in ServerLoop ()
3 #20 0x000000000072f11e in PostmasterMain ()
2 #21 0x000000000048b854 in main ()Does that shed any light?
Seems like some of the processes are taking a long time or stuck while
reading/writing SLRU pages, and due to that while creating a new
connection the backend process is not able to check the transaction
status (from pg_xlog) of the pg_class tuple and gets stuck/taking a
long time in a startup.
--
Regards,
Dilip Kumar
EnterpriseDB: http://www.enterprisedb.com
On Thu, Nov 25, 2021 at 9:50 AM Dilip Kumar <dilipbalaut@gmail.com> wrote:
On Thu, Nov 25, 2021 at 8:58 AM James Sewell <james.sewell@jirotech.com> wrote:
The hypothesis I'm thinking of is that incoming sessions are being blocked
somewhere before they can acquire a ProcArray entry; if so, they'd not
show up in either pg_stat_activity or pg_locks. What we have to look for
then is evidence of somebody holding a strong lock on a shared relation.
Try "select * from pg_locks where locktype = 'relation' and database = 0".That doesn't show anything when the issue is happening.
Strace shows the startup processes looping like so:
13:51:15.510850 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=733559666}) = 0
13:51:15.511254 futex(0x7ee891405238, FUTEX_WAKE, 1) = 1
13:51:15.511422 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=734037545}) = 0
13:51:15.511690 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.520470 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=743136450}) = 0
13:51:15.520772 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=743376746}) = 0
13:51:15.521005 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.539309 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=761920081}) = 0
13:51:15.539508 futex(0x7ee891406bb8, FUTEX_WAKE, 1) = 1
13:51:15.539690 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=762298276}) = 0
13:51:15.539882 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.547311 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=769929341}) = 0
13:51:15.547757 futex(0x7ee89140a738, FUTEX_WAKE, 1) = 1
13:51:15.547931 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=770524120}) = 0
13:51:15.548089 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.551482 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = -1 EAGAIN (Resource temporarily unavailable)
13:51:15.551950 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.593631 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = -1 EAGAIN (Resource temporarily unavailable)
13:51:15.593807 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.626167 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.627590 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=850204434}) = 0
13:51:15.627817 futex(0x7ee8914033b8, FUTEX_WAKE, 1) = 1
13:51:15.627987 open("pg_subtrans/A100", O_RDWR) = 16
13:51:15.628270 lseek(16, 131072, SEEK_SET) = 131072
13:51:15.628461 read(16, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = 8192
13:51:15.628677 close(16) = 0
13:51:15.628911 open("pg_subtrans/A0E1", O_RDWR) = 16
13:51:15.629132 lseek(16, 122880, SEEK_SET) = 122880
13:51:15.629309 read(16, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = 8192
13:51:15.629503 close(16) = 0
13:51:15.629685 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=852272645}) = 0
13:51:15.629863 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.656694 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=879314944}) = 0
13:51:15.656923 futex(0x7ee8914125b8, FUTEX_WAKE, 1) = 1
13:51:15.657129 open("pg_subtrans/A0EE", O_RDWR) = 16
13:51:15.657385 lseek(16, 73728, SEEK_SET) = 73728
13:51:15.657638 read(16, "\0\0\0\0\0H\356\240\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\5H\356\240\0\0\0\0"..., 8192) = 8192
13:51:15.657907 close(16) = 0
13:51:15.658141 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=880753952}) = 0
13:51:15.658346 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.689705 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=912331058}) = 0
13:51:15.689950 futex(0x7ee89140a0b8, FUTEX_WAKE, 1) = 1
13:51:15.690182 futex(0x7ee8914118b8, FUTEX_WAKE, 1) = 1
13:51:15.690420 open("pg_subtrans/A0EE", O_RDWR) = 16
13:51:15.690742 lseek(16, 73728, SEEK_SET) = 73728
13:51:15.691037 read(16, "\0\0\0\0\0H\356\240\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\5H\356\240\0\0\0\0"..., 8192) = 8192
13:51:15.691303 close(16) = 0
13:51:15.691582 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=914202777}) = 0
13:51:15.691837 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.713319 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.716423 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=939067321}) = 0
13:51:15.716737 futex(0x7ee89140a0b8, FUTEX_WAKE, 1) = 1
13:51:15.717010 futex(0x7ee89140f3b8, FUTEX_WAKE, 1) = 1
13:51:15.717286 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=939899218}) = 0
13:51:15.717578 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.722270 futex(0x7ee891405938, FUTEX_WAIT, 0, NULL) = 0
13:51:15.746391 clock_gettime(CLOCK_MONOTONIC, {tv_sec=19439358, tv_nsec=969020657}) = 0
13:51:15.746664 futex(0x7ee89140fa38, FUTEX_WAKE, 1) = 1
13:51:15.746877 open("pg_subtrans/A0EE", O_RDWR) = 16While gdb shows similar to:
24 ^[[?1034h(gdb) bt
23 #0 0x00007f18fb9deb3b in do_futex_wait.constprop.1 () from /lib64/libpthread.so.0
22 #1 0x00007f18fb9debcf in __new_sem_wait_slow.constprop.0 () from /lib64/libpthread.so.0
21 #2 0x00007f18fb9dec6b in sem_wait@@GLIBC_2.2.5 () from /lib64/libpthread.so.0
20 #3 0x000000000071c482 in PGSemaphoreLock ()
19 #4 0x000000000079078c in LWLockAcquire ()
18 #5 0x00000000004fa9ae in SimpleLruWaitIO.isra.1 ()
17 #6 0x00000000004fb2a4 in SimpleLruReadPage ()
16 #7 0x00000000004fbc07 in SubTransGetParent ()
15 #8 0x00000000004fbc57 in SubTransGetTopmostTransaction ()
14 #9 0x00000000008f65a7 in XidInMVCCSnapshot ()
13 #10 0x00000000008f662e in HeapTupleSatisfiesMVCC ()
12 #11 0x00000000004c436e in heapgetpage ()
11 #12 0x00000000004c58e4 in heap_getnext ()
10 #13 0x00000000008ab8b5 in ScanPgRelation ()
9 #14 0x00000000008ae124 in RelationBuildDesc ()
8 #15 0x00000000008b010e in load_critical_index ()
7 #16 0x00000000008b39ac in RelationCacheInitializePhase3 ()
6 #17 0x00000000008cbd56 in InitPostgres ()
5 #18 0x00000000007a1cfe in PostgresMain ()
4 #19 0x000000000048a9c0 in ServerLoop ()
3 #20 0x000000000072f11e in PostmasterMain ()
2 #21 0x000000000048b854 in main ()Does that shed any light?
Seems like some of the processes are taking a long time or stuck while
reading/writing SLRU pages, and due to that while creating a new
connection the backend process is not able to check the transaction
status (from pg_xlog) of the pg_class tuple and gets stuck/taking a
long time in a startup.
My next question would be whether this particular process shown is
stack is stuck forever or finally, it is able to make a connection? I
want to understand is this just due to slow I/O or something else?
--
Regards,
Dilip Kumar
EnterpriseDB: http://www.enterprisedb.com
On Thu, Nov 25, 2021 at 9:50 AM Dilip Kumar <dilipbalaut@gmail.com> wrote:
Does that shed any light?
Seems like some of the processes are taking a long time or stuck while
reading/writing SLRU pages, and due to that while creating a new
connection the backend process is not able to check the transaction
status (from pg_xlog) of the pg_class tuple and gets stuck/taking a
long time in a startup.
Correction, I mean pg_xact (pg_clog in older version) not pg_xlog :)
--
Regards,
Dilip Kumar
EnterpriseDB: http://www.enterprisedb.com
Seems like some of the processes are taking a long time or stuck while
reading/writing SLRU pages, and due to that while creating a new
connection the backend process is not able to check the transaction
status (from pg_xlog) of the pg_class tuple and gets stuck/taking a
long time in a startup.My next question would be whether this particular process shown is
stack is stuck forever or finally, it is able to make a connection? I
want to understand is this just due to slow I/O or something else?
They don't ever seem to clear, (more and more show up) and IO doesn't seem
to be deadlocked at that time.
It's a really odd one!
--
The contents of this email are confidential and may be subject to legal or
professional privilege and copyright. No representation is made that this
email is free of viruses or other defects. If you have received this
communication in error, you may not copy or distribute any part of it or
otherwise disclose its contents to anyone. Please advise the sender of your
incorrect receipt of this correspondence.
On Thu, Nov 25, 2021 at 10:53 AM James Sewell <james.sewell@jirotech.com> wrote:
Seems like some of the processes are taking a long time or stuck while
reading/writing SLRU pages, and due to that while creating a new
connection the backend process is not able to check the transaction
status (from pg_xlog) of the pg_class tuple and gets stuck/taking a
long time in a startup.My next question would be whether this particular process shown is
stack is stuck forever or finally, it is able to make a connection? I
want to understand is this just due to slow I/O or something else?They don't ever seem to clear, (more and more show up) and IO doesn't seem to be deadlocked at that time.
How did you verify that, maybe some process started IO and stuck
there? Can we check pg_stat_activity that is there some process that
shows in the wait event as SLRURead/SLRUWrite and not coming out of
that state?
--
Regards,
Dilip Kumar
EnterpriseDB: http://www.enterprisedb.com
