Re: Database logins taking longer and longer, showing up as "authentication" in ps(1) - Mailing list pgsql-general

Adam writes:

> I will try to look at pg_stat_activity and pg_locks the next time

I did not have to wait long, so I have captured the output of
pg_stat_activity and pg_locks when everything is fine, by just doing
"time sudo -u postgres PAGER=cat psql template1 -c 'SELECT * FROM
pg_stat_activity'; time sudo -u postgres PAGER=cat psql template1 -c
'SELECT * FROM pg_locks'":

 · https://koldfront.dk/misc/postgresql/pg_stat_activity_pg_locks-OK.txt.gz

And while it was bad, and I shut down the workers (notice how the first
psql took 23s compared to 0.112s when everything was fine):

 · https://koldfront.dk/misc/postgresql/pg_stat_activity_pg_locks-BAD.txt.gz

(I have "sanitized" both files for usernames, application names,
IP-addresses and queries.)

I also attached gdb to one of the processes and got a backtrace, gdb
continued, pressed ^C after ~5s, got a backtrace and kept doing that for
a while, this is the result:

  postgres  79572  0.0  0.0 34686088 8412 ?       Ss   15:15   0:00  \_ postgres: 11/main: workqueue XXdb
127.0.0.1(53126)authentication 
  postgres  79573  0.0  0.0 34686088 6476 ?       Ss   15:15   0:00  \_ postgres: 11/main: anonymous XXdb
127.0.0.1(53128)authentication 
  $ sudo gdb -p 79572
  GNU gdb (Ubuntu 7.11.1-0ubuntu1~16.5) 7.11.1
     [...]
  Attaching to process 79572
     [...]
  Reading symbols from /usr/lib/postgresql/11/bin/postgres...(no debugging symbols found)...done.
     [...]
  0x00007f8272cf2827 in futex_abstimed_wait_cancelable (private=128, abstime=0x0, expected=0,
futex_word=0x7f7a2e9f6d38)at ../sysdeps/unix/sysv/linux/futex-internal.h:205 
  205    ../sysdeps/unix/sysv/linux/futex-internal.h: No such file or directory.
  (gdb) bt
  #0  0x00007f8272cf2827 in futex_abstimed_wait_cancelable (private=128, abstime=0x0, expected=0,
futex_word=0x7f7a2e9f6d38)at ../sysdeps/unix/sysv/linux/futex-internal.h:205 
  #1  do_futex_wait (sem=sem@entry=0x7f7a2e9f6d38, abstime=0x0) at sem_waitcommon.c:111
  #2  0x00007f8272cf28d4 in __new_sem_wait_slow (sem=0x7f7a2e9f6d38, abstime=0x0) at sem_waitcommon.c:181
  #3  0x00007f8272cf297a in __new_sem_wait (sem=<optimized out>) at sem_wait.c:29
  #4  0x000055f60d36c252 in PGSemaphoreLock ()
  #5  0x000055f60d3e35cc in LWLockAcquire ()
  #6  0x000055f60d3d14ee in ProcArrayAdd ()
  #7  0x000055f60d3e01a3 in InitProcessPhase2 ()
  #8  0x000055f60d51c99b in InitPostgres ()
  #9  0x000055f60d3f2baf in PostgresMain ()
  #10 0x000055f60d102bf8 in ?? ()
  #11 0x000055f60d37e492 in PostmasterMain ()
  #12 0x000055f60d103fa5 in main ()
  (gdb) cont
  Continuing.
  ^C
  Program received signal SIGINT, Interrupt.
  0x00007f8272cf2827 in futex_abstimed_wait_cancelable (private=128, abstime=0x0, expected=0,
futex_word=0x7f7a2e9f6d38)at ../sysdeps/unix/sysv/linux/futex-internal.h:205 
  205    in ../sysdeps/unix/sysv/linux/futex-internal.h
  (gdb) bt
  #0  0x00007f8272cf2827 in futex_abstimed_wait_cancelable (private=128, abstime=0x0, expected=0,
futex_word=0x7f7a2e9f6d38)at ../sysdeps/unix/sysv/linux/futex-internal.h:205 
  #1  do_futex_wait (sem=sem@entry=0x7f7a2e9f6d38, abstime=0x0) at sem_waitcommon.c:111
  #2  0x00007f8272cf28d4 in __new_sem_wait_slow (sem=0x7f7a2e9f6d38, abstime=0x0) at sem_waitcommon.c:181
  #3  0x00007f8272cf297a in __new_sem_wait (sem=<optimized out>) at sem_wait.c:29
  #4  0x000055f60d36c252 in PGSemaphoreLock ()
  #5  0x000055f60d3e35cc in LWLockAcquire ()
  #6  0x000055f60d3d14ee in ProcArrayAdd ()
  #7  0x000055f60d3e01a3 in InitProcessPhase2 ()
  #8  0x000055f60d51c99b in InitPostgres ()
  #9  0x000055f60d3f2baf in PostgresMain ()
  #10 0x000055f60d102bf8 in ?? ()
  #11 0x000055f60d37e492 in PostmasterMain ()
  #12 0x000055f60d103fa5 in main ()
  (gdb) cont
  Continuing.
  ^C
  Program received signal SIGINT, Interrupt.
  0x00007f8272cf2827 in futex_abstimed_wait_cancelable (private=128, abstime=0x0, expected=0,
futex_word=0x7f7a2e9f6d38)at ../sysdeps/unix/sysv/linux/futex-internal.h:205 
  205    in ../sysdeps/unix/sysv/linux/futex-internal.h
  (gdb) bt
  #0  0x00007f8272cf2827 in futex_abstimed_wait_cancelable (private=128, abstime=0x0, expected=0,
futex_word=0x7f7a2e9f6d38)at ../sysdeps/unix/sysv/linux/futex-internal.h:205 
  #1  do_futex_wait (sem=sem@entry=0x7f7a2e9f6d38, abstime=0x0) at sem_waitcommon.c:111
  #2  0x00007f8272cf28d4 in __new_sem_wait_slow (sem=0x7f7a2e9f6d38, abstime=0x0) at sem_waitcommon.c:181
  #3  0x00007f8272cf297a in __new_sem_wait (sem=<optimized out>) at sem_wait.c:29
  #4  0x000055f60d36c252 in PGSemaphoreLock ()
  #5  0x000055f60d3e35cc in LWLockAcquire ()
  #6  0x000055f60d3d14ee in ProcArrayAdd ()
  #7  0x000055f60d3e01a3 in InitProcessPhase2 ()
  #8  0x000055f60d51c99b in InitPostgres ()
  #9  0x000055f60d3f2baf in PostgresMain ()
  #10 0x000055f60d102bf8 in ?? ()
  #11 0x000055f60d37e492 in PostmasterMain ()
  #12 0x000055f60d103fa5 in main ()
  (gdb) cont
  Continuing.
  ^C
  Program received signal SIGINT, Interrupt.
  0x00007f8272cf2827 in futex_abstimed_wait_cancelable (private=128, abstime=0x0, expected=0,
futex_word=0x7f7a2e9f6d38)at ../sysdeps/unix/sysv/linux/futex-internal.h:205 
  205    in ../sysdeps/unix/sysv/linux/futex-internal.h
  (gdb) bt
  #0  0x00007f8272cf2827 in futex_abstimed_wait_cancelable (private=128, abstime=0x0, expected=0,
futex_word=0x7f7a2e9f6d38)at ../sysdeps/unix/sysv/linux/futex-internal.h:205 
  #1  do_futex_wait (sem=sem@entry=0x7f7a2e9f6d38, abstime=0x0) at sem_waitcommon.c:111
  #2  0x00007f8272cf28d4 in __new_sem_wait_slow (sem=0x7f7a2e9f6d38, abstime=0x0) at sem_waitcommon.c:181
  #3  0x00007f8272cf297a in __new_sem_wait (sem=<optimized out>) at sem_wait.c:29
  #4  0x000055f60d36c252 in PGSemaphoreLock ()
  #5  0x000055f60d3e35cc in LWLockAcquire ()
  #6  0x000055f60d3d14ee in ProcArrayAdd ()
  #7  0x000055f60d3e01a3 in InitProcessPhase2 ()
  #8  0x000055f60d51c99b in InitPostgres ()
  #9  0x000055f60d3f2baf in PostgresMain ()
  #10 0x000055f60d102bf8 in ?? ()
  #11 0x000055f60d37e492 in PostmasterMain ()
  #12 0x000055f60d103fa5 in main ()
  (gdb) cont
  Continuing.
  ^C
  Program received signal SIGINT, Interrupt.
  0x00007f8272cf2827 in futex_abstimed_wait_cancelable (private=128, abstime=0x0, expected=0,
futex_word=0x7f7a2e9f6d38)at ../sysdeps/unix/sysv/linux/futex-internal.h:205 
  205    in ../sysdeps/unix/sysv/linux/futex-internal.h
  (gdb) bt
  #0  0x00007f8272cf2827 in futex_abstimed_wait_cancelable (private=128, abstime=0x0, expected=0,
futex_word=0x7f7a2e9f6d38)at ../sysdeps/unix/sysv/linux/futex-internal.h:205 
  #1  do_futex_wait (sem=sem@entry=0x7f7a2e9f6d38, abstime=0x0) at sem_waitcommon.c:111
  #2  0x00007f8272cf28d4 in __new_sem_wait_slow (sem=0x7f7a2e9f6d38, abstime=0x0) at sem_waitcommon.c:181
  #3  0x00007f8272cf297a in __new_sem_wait (sem=<optimized out>) at sem_wait.c:29
  #4  0x000055f60d36c252 in PGSemaphoreLock ()
  #5  0x000055f60d3e35cc in LWLockAcquire ()
  #6  0x000055f60d3d14ee in ProcArrayAdd ()
  #7  0x000055f60d3e01a3 in InitProcessPhase2 ()
  #8  0x000055f60d51c99b in InitPostgres ()
  #9  0x000055f60d3f2baf in PostgresMain ()
  #10 0x000055f60d102bf8 in ?? ()
  #11 0x000055f60d37e492 in PostmasterMain ()
  #12 0x000055f60d103fa5 in main ()
  (gdb) cont
  Continuing.
  ^C
  Program received signal SIGINT, Interrupt.
  0x00007f8272cf2827 in futex_abstimed_wait_cancelable (private=128, abstime=0x0, expected=0,
futex_word=0x7f7a2e9f6d38)at ../sysdeps/unix/sysv/linux/futex-internal.h:205 
  205    in ../sysdeps/unix/sysv/linux/futex-internal.h
  (gdb) bt
  #0  0x00007f8272cf2827 in futex_abstimed_wait_cancelable (private=128, abstime=0x0, expected=0,
futex_word=0x7f7a2e9f6d38)at ../sysdeps/unix/sysv/linux/futex-internal.h:205 
  #1  do_futex_wait (sem=sem@entry=0x7f7a2e9f6d38, abstime=0x0) at sem_waitcommon.c:111
  #2  0x00007f8272cf28d4 in __new_sem_wait_slow (sem=0x7f7a2e9f6d38, abstime=0x0) at sem_waitcommon.c:181
  #3  0x00007f8272cf297a in __new_sem_wait (sem=<optimized out>) at sem_wait.c:29
  #4  0x000055f60d36c252 in PGSemaphoreLock ()
  #5  0x000055f60d3e35cc in LWLockAcquire ()
  #6  0x000055f60d3d14ee in ProcArrayAdd ()
  #7  0x000055f60d3e01a3 in InitProcessPhase2 ()
  #8  0x000055f60d51c99b in InitPostgres ()
  #9  0x000055f60d3f2baf in PostgresMain ()
  #10 0x000055f60d102bf8 in ?? ()
  #11 0x000055f60d37e492 in PostmasterMain ()
  #12 0x000055f60d103fa5 in main ()
  (gdb) cont
  Continuing.
  ^C
  Program received signal SIGINT, Interrupt.
  0x00007f8270a039f3 in delete_module () at ../sysdeps/unix/syscall-template.S:86
  86    ../sysdeps/unix/syscall-template.S: No such file or directory.
  (gdb) bt
  #0  0x00007f8270a039f3 in delete_module () at ../sysdeps/unix/syscall-template.S:86
  #1  0x000055f60d3d0101 in WaitEventSetWait ()
  #2  0x000055f60d2dccff in secure_read ()
  #3  0x000055f60d2e9138 in ?? ()
  #4  0x000055f60d2e9e75 in pq_getbyte ()
  #5  0x000055f60d3f3100 in PostgresMain ()
  #6  0x000055f60d102bf8 in ?? ()
  #7  0x000055f60d37e492 in PostmasterMain ()
  #8  0x000055f60d103fa5 in main ()
  (gdb) cont
  Continuing.
  ^C
  Program received signal SIGINT, Interrupt.
  0x00007f8270a039f3 in delete_module () at ../sysdeps/unix/syscall-template.S:86
  86    in ../sysdeps/unix/syscall-template.S
  (gdb) detach
  Detaching from program: /usr/lib/postgresql/11/bin/postgres, process 79572
  (gdb) quit

I hope this is useful. Let me know if there are any parameters I should
try adjusting, or some other information I should try to extract. Thanks!


  Best regards,

    Adam

--
 "Why do you ask so much?"                                  Adam Sjøgren
 "I'm a kid. It's what we do."                         asjo@koldfront.dk