Re: Database logins taking longer and longer, showing up as "authentication" in ps(1)

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(at)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(at)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(at)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(at)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(at)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(at)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(at)koldfront(dot)dk