Search Postgresql Archives

backends stuck in "startup"

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



I'm sorry to report this previously reported problem is happening again,
starting shortly after pg_upgrading a customer to PG10.1 from 9.6.5.

As $subject: backends are stuck in startup for minutes at a time.  I didn't
strace this time, but I believe last time I saw one was waiting in a futex.

postgres 25271 17665  0 16:54 ?        00:00:00 postgres: oooo oooo a.b.c.246(59980) startup    
postgres 27123 17665  0 16:55 ?        00:00:00 postgres: mmmmmmmm mmmmmmmm a.b.c.247(59919) startup
postgres 27142 17665  0 16:55 ?        00:00:00 postgres: main main a.b.c.100(42892) startup    
postgres 27224 17665  0 16:56 ?        00:00:00 postgres: main main a.b.c.100(42898) startup    
postgres 27270 17665  0 16:56 ?        00:00:00 postgres: wwwwww wwwwww a.b.c.252(39760) startup
postgres 27271 17665  0 16:56 ?        00:00:00 postgres: iiiiiii iiiiiii a.b.c.248(37224) startup
postgres 27873 17665  0 16:58 ?        00:00:00 postgres: wwwwwwww wwwwwwww a.b.c.253(59667) startup
postgres 30038 17665  0 17:00 ?        00:00:00 postgres: wwwwww wwwwww a.b.c.252(39780) startup
postgres 30039 17665  0 17:00 ?        00:00:00 postgres: oooo oooo a.b.c.246(60014) startup    
postgres 30040 17665  0 17:00 ?        00:00:00 postgres: mmmmmmmm mmmmmmmm a.b.c.247(59951) startup
postgres 30041 17665  0 17:00 ?        00:00:00 postgres: mmmmmmmm mmmmmmmm a.b.c.247(59952) startup
postgres 30042 17665  0 17:00 ?        00:00:00 postgres: wwwwww wwwwww a.b.c.252(39788) startup
postgres 30043 17665  0 17:00 ?        00:00:00 postgres: aaaaa aaaaa a.b.c.245(44819) startup  
postgres 30044 17665  0 17:00 ?        00:00:00 postgres: nnn nnn a.b.c.250(41317) startup      
postgres 30045 17665  0 17:00 ?        00:00:00 postgres: mmmmmm mmmmmm a.b.c.249(47876) startup
postgres 30046 17665  0 17:00 ?        00:00:00 postgres: nnn nnn a.b.c.250(41320) startup      
postgres 30048 17665  0 17:00 ?        00:00:00 postgres: aaaaa aaaaa a.b.c.245(44834) startup  
postgres 30051 17665  0 17:00 ?        00:00:00 postgres: iiiiiii iiiiiii a.b.c.248(37244) startup
postgres 30052 17665  0 17:00 ?        00:00:00 postgres: iiiiiii iiiiiii a.b.c.248(37247) startup
postgres 30054 17665  0 17:00 ?        00:00:00 postgres: nnn nnn a.b.c.250(41327) startup      
postgres 30079 17665  0 17:00 ?        00:00:00 postgres: aaaaa aaaaa a.b.c.245(44843) startup  
postgres 30081 17665  0 17:00 ?        00:00:00 postgres: wwwwww wwwwww a.b.c.252(39790) startup
postgres 30083 17665  0 17:00 ?        00:00:00 postgres: pppp pppp a.b.c.251(50397) startup    
postgres 30084 17665  0 17:00 ?        00:00:00 postgres: main main a.b.c.100(43074) startup    
postgres 30604 17665  0 17:02 ?        00:00:00 postgres: oooo oooo a.b.c.246(60018) startup    
postgres 30614 17665  0 17:02 ?        00:00:00 postgres: nnn nnn a.b.c.250(41331) startup      
postgres 30624 17665  0 17:02 ?        00:00:00 postgres: aaaaa aaaaa a.b.c.245(44847) startup  
postgres 30841 17665  0 17:03 ?        00:00:00 postgres: mmmmmmmm mmmmmmmm a.b.c.247(59961) startup
postgres 31023 17665  0 17:03 ?        00:00:00 postgres: postgres main [local] startup               
postgres 31024 17665  0 17:03 ?        00:00:00 postgres: wwwwww wwwwww a.b.c.252(39796) startup

I found these older, similar reports:
https://www.postgresql.org/message-id/flat/4F9AC452.3050102%40pgexperts.com#4F9AC452.3050102@xxxxxxxxxxxxx
https://www.postgresql.org/message-id/8896.1337998337%40sss.pgh.pa.us

I saved ~40 cores from backends from the most recent incident, which are all
essentially identical:

(gdb) bt
#0  0x0000003f6ee0d930 in ?? ()
#1  0x00007f19f3401258 in ?? ()
#2  0x00000000006a4440 in PGSemaphoreLock (sema=0x7f19f3401258) at pg_sema.c:310
#3  0x0000000000714495 in LWLockAcquire (lock=0x7f19f3404f80, mode=LW_SHARED) at lwlock.c:1233
#4  0x00000000006f75e5 in BufferAlloc (smgr=0x1f3bc48, relpersistence=112 'p', forkNum=MAIN_FORKNUM, blockNum=1, mode=RBM_NORMAL, strategy=0x0, 
    hit=0x7fff6ef1c5af "") at bufmgr.c:1012
#5  ReadBuffer_common (smgr=0x1f3bc48, relpersistence=112 'p', forkNum=MAIN_FORKNUM, blockNum=1, mode=RBM_NORMAL, strategy=0x0, hit=0x7fff6ef1c5af "")
    at bufmgr.c:745
#6  0x00000000006f800e in ReadBufferExtended (reln=0x1ee6a08, forkNum=MAIN_FORKNUM, blockNum=1, mode=<value optimized out>, 
    strategy=<value optimized out>) at bufmgr.c:664
#7  0x00000000004c090a in _bt_relandgetbuf (rel=0x1ee6a08, obuf=145, blkno=<value optimized out>, access=1) at nbtpage.c:708
#8  0x00000000004c1284 in _bt_getroot (rel=0x1ee6a08, access=<value optimized out>) at nbtpage.c:298
#9  0x00000000004c46eb in _bt_search (rel=0x1ee6a08, keysz=1, scankey=0x7fff6ef1d040, nextkey=0 '\000', bufP=0x7fff6ef1da4c, access=1, snapshot=0x1f1a648)
    at nbtsearch.c:103
#10 0x00000000004c5d1d in _bt_first (scan=0x1f1a4a8, dir=ForwardScanDirection) at nbtsearch.c:1028
#11 0x00000000004c39dd in btgettuple (scan=0x1f1a4a8, dir=ForwardScanDirection) at nbtree.c:372
#12 0x00000000004bcf1a in index_getnext_tid (scan=0x1f1a4a8, direction=<value optimized out>) at indexam.c:541
#13 0x00000000004bcfca in index_getnext (scan=0x1f1a4a8, direction=ForwardScanDirection) at indexam.c:679
#14 0x00000000004bc549 in systable_getnext (sysscan=0x1f1ae68) at genam.c:422
#15 0x000000000080fac7 in SearchCatCache (cache=0x1ece848, v1=<value optimized out>, v2=<value optimized out>, v3=<value optimized out>, 
    v4=<value optimized out>) at catcache.c:1178
#16 0x0000000000844e7d in superuser_arg (roleid=33320) at superuser.c:71
#17 0x0000000000832917 in InitPostgres (in_dbname=0x1e9eec8 "iiiiiii", dboid=0, username=0x1e71738 "iiiiiii", useroid=0, out_dbname=0x0) at postinit.c:742
#18 0x00000000007239f2 in PostgresMain (argc=1, argv=<value optimized out>, dbname=0x1e9eec8 "iiiiiii", username=0x1e71738 "iiiiiii") at postgres.c:3735
#19 0x00000000006b7d7a in BackendRun (argc=<value optimized out>, argv=<value optimized out>) at postmaster.c:4357
#20 BackendStartup (argc=<value optimized out>, argv=<value optimized out>) at postmaster.c:4029
#21 ServerLoop (argc=<value optimized out>, argv=<value optimized out>) at postmaster.c:1753
#22 PostmasterMain (argc=<value optimized out>, argv=<value optimized out>) at postmaster.c:1361
#23 0x0000000000638ad0 in main (argc=3, argv=0x1e6f5b0) at main.c:228

(gdb) p *reln
$2 = {rd_node = {spcNode = 1663, dbNode = 16405, relNode = 2679}...

nep=# SELECT relname FROM pg_class WHERE oid=2679;
relname | pg_index_indexrelid_index

For the largest DB:
main=# \dt+ pg_class|pg_attribute|pg_index
 pg_catalog | pg_attribute | table | postgres | 227 MB  | 
 pg_catalog | pg_class     | table | postgres | 6752 kB | 
 pg_catalog | pg_index     | table | postgres | 3448 kB | 

During normal operation, after restarting following this incident:

postgres=# SELECT COUNT(1) FROM pg_stat_activity;
count | 85

shared_buffers | 2GB
max_connections | 400
effective_cache_size | 4GB
maintenance_work_mem | 512MB
effective_io_concurrency | 2
max_locks_per_transaction | 64
max_parallel_workers_per_gather | 3
password_encryption | scram-sha-256

I can probably collect other diagnostics if needed, but otherwise it's possible
I'll need to reload this DB under PG96.

..but, while this issue is occuring, I can't make simple queries
(like SELECT * FROM pg_locks)

Notes:
 - we DO use temp tables; it looks like we created up to 90 temp tables each hour;
 - we're still running analyze following yesterday's pg_upgrade;
 - I have a script saving something from pg_buffercache, but it doesn't appear
   to be running during this last incident;
 - I'm planning do disable sync seqscan for the night (although as I understand
   that may not matter (?))
 - this instance has clients connecting to ~10 DBs;

Thanks in advance
Justin




[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
[Index of Archives]     [Postgresql Jobs]     [Postgresql Admin]     [Postgresql Performance]     [Linux Clusters]     [PHP Home]     [PHP on Windows]     [Kernel Newbies]     [PHP Classes]     [PHP Books]     [PHP Databases]     [Postgresql & PHP]     [Yosemite]

  Powered by Linux