Re: 9.1.3 backends getting stuck in 'startup'

On 04/27/12 11:54, Jeff Frost wrote:
> On 04/27/12 10:14, Tom Lane wrote:
>> Jeff Frost <jeff(at)pgexperts(dot)com> writes:
>>> A few times today, we've seen postgresql 9.1.3 backends on Ubuntu 11.10 x86_64
>>> get stuck in 'startup' mode.
>> Well, the one you backtraced seems to be waiting for somebody else to
>> release one of the buffer mapping locks ... which is not a lock I'd
>> expect to get held long, ever. Could you check all the Postgres
>> processes and see which of them have backtraces different from that?
>> We need to figure out what's sitting on that lock and why.
>>
> Thanks Tom. We've failed over to the replica which seems to have the issue
> happen less often, so I'll try and get the backtraces as soon as it's reproduced.
Alright, found one that's a little different (at least it wasn't in InitPostgres):

#0 0x00007f252f612297 in semop () at ../sysdeps/unix/syscall-template.S:82
#1 0x00007f253160ccc0 in PGSemaphoreLock (sema=0x7f252ba65c00, interruptOK=0
'\000') at pg_sema.c:418
#2 0x00007f253164cea5 in LWLockAcquire (lockid=<value optimized out>,
mode=LW_SHARED) at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/storage/lmgr/lwlock.c:464
#3 0x00007f253163889a in BufferAlloc (smgr=0x7f2532c79f60,
relpersistence=<value optimized out>, forkNum=<value optimized out>,
blockNum=<value optimized out>, mode=<value optimized out>, strategy=<value
optimized out>, hit=0x7fffea5f9ecf "") at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/storage/buffer/bufmgr.c:531
#4 ReadBuffer_common (smgr=0x7f2532c79f60, relpersistence=<value optimized
out>, forkNum=<value optimized out>, blockNum=<value optimized out>,
mode=<value optimized out>, strategy=<value optimized out>, hit=0x7fffea5f9ecf
"") at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/storage/buffer/bufmgr.c:325
#5 0x00007f25316391e4 in ReadBufferExtended (reln=0x7f231ee95438,
forkNum=MAIN_FORKNUM, blockNum=166364, mode=RBM_NORMAL, strategy=0xecaf9628)
at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/storage/buffer/bufmgr.c:246
#6 0x00007f2531490fa3 in _bt_relandgetbuf (rel=0x7f231ee95438, obuf=77863,
blkno=1, access=1) at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/access/nbtree/nbtpage.c:651
#7 0x00007f2531494cda in _bt_search (rel=0x7f231ee95438, keysz=1,
scankey=0x7fffea5f9ff0, nextkey=<value optimized out>, bufP=0x7fffea5fa9fc,
access=<value optimized out>) at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/access/nbtree/nbtsearch.c:121
#8 0x00007f25314951bf in _bt_first (scan=<value optimized out>, dir=<value
optimized out>) at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/access/nbtree/nbtsearch.c:841
#9 0x00007f2531493954 in btgettuple (fcinfo=<value optimized out>) at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/access/nbtree/nbtree.c:315
#10 0x00007f2531721003 in FunctionCall2Coll (flinfo=0x0, collation=3932134720,
arg1=1, arg2=18446744073709551615) at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/utils/fmgr/fmgr.c:1319
#11 0x00007f253148d0d5 in index_getnext (scan=0x7f2532eff820, direction=<value
optimized out>) at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/access/index/indexam.c:499
#12 0x00007f25316c392e in get_actual_variable_range (root=<value optimized
out>, vardata=<value optimized out>, sortop=<value optimized out>, min=<value
optimized out>, max=0x7f2532efc8e0) at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/utils/adt/selfuncs.c:4748
#13 0x00007f25316c7969 in ineq_histogram_selectivity (root=<value optimized
out>, vardata=0x7fffea5fb250, opproc=<value optimized out>, isgt=0 '\000',
constval=<value optimized out>, consttype=<value optimized out>) at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/utils/adt/selfuncs.c:805
#14 0x00007f25316c810c in scalarineqsel (root=0x7f2532d18c00, operator=<value
optimized out>, isgt=-1 '\377', vardata=0x7fffea5fb250, constval=47095179,
consttype=<value optimized out>) at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/utils/adt/selfuncs.c:535
#15 0x00007f25316c85fc in mergejoinscansel (root=0x7f2532d18c00, clause=<value
optimized out>, opfamily=<value optimized out>, strategy=<value optimized
out>, nulls_first=0 '\000', leftstart=0x7fffea5fb468, leftend=0x7fffea5fb460,
rightstart=0x7fffea5fb458, rightend=0x7fffea5fb450) at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/utils/adt/selfuncs.c:2843
#16 0x00007f25315e11d3 in cached_scansel (path=0x7f2532efbac0,
root=0x7f2532d18c00, sjinfo=<value optimized out>) at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/optimizer/path/costsize.c:2099
#17 cost_mergejoin (path=0x7f2532efbac0, root=0x7f2532d18c00, sjinfo=<value
optimized out>) at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/optimizer/path/costsize.c:1847
#18 0x00007f2531605e40 in create_mergejoin_path (root=0x7f2532d18c00,
joinrel=0x7f2532efbbf0, jointype=JOIN_LEFT, sjinfo=0x7f2532ef3180,
outer_path=0x7f2532ef6e50, inner_path=<value optimized out>,
restrict_clauses=0x7f2532efc310, pathkeys=0x0, mergeclauses=0x7f2532efc540,
outersortkeys=0x7f2532efc4f0, innersortkeys=0x7f2532efc590) at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/optimizer/util/pathnode.c:1554
#19 0x00007f25315e8559 in sort_inner_and_outer (root=0x7f2532d18c00,
joinrel=0x7f2532efbbf0, outerrel=<value optimized out>, innerrel=<value
optimized out>, jointype=<value optimized out>, sjinfo=<value optimized out>,
restrictlist=0x7f2532efc310) at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/optimizer/path/joinpath.c:305
#20 add_paths_to_joinrel (root=0x7f2532d18c00, joinrel=0x7f2532efbbf0,
outerrel=<value optimized out>, innerrel=<value optimized out>,
jointype=<value optimized out>, sjinfo=<value optimized out>,
restrictlist=0x7f2532efc310) at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/optimizer/path/joinpath.c:103
#21 0x00007f25315ea08b in make_join_rel (root=0x7f2532d18c00,
rel1=0x7f2532ee29d0, rel2=0x7f2532ee3b00) at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/optimizer/path/joinrels.c:642
#22 0x00007f25315ea339 in make_rels_by_clause_joins (root=0x7f2532d18c00,
level=<value optimized out>) at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/optimizer/path/joinrels.c:268
#23 join_search_one_level (root=0x7f2532d18c00, level=<value optimized out>)
at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/optimizer/path/joinrels.c:99
#24 0x00007f25315dc40b in standard_join_search (root=0x7f2532d18c00,
levels_needed=8, initial_rels=<value optimized out>) at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/optimizer/path/allpaths.c:1108
#25 0x00007f25315dd7cb in make_rel_from_joinlist (root=0x7f2532d18c00,
joinlist=<value optimized out>) at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/optimizer/path/allpaths.c:1004
#26 0x00007f25315f3e76 in query_planner (root=0x7f2532d18c00, tlist=<value
optimized out>, tuple_fraction=0, limit_tuples=<value optimized out>,
cheapest_path=0x7fffea5fb9e0, sorted_path=<value optimized out>,
num_groups=0x7fffea5fb9e8) at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/optimizer/plan/planmain.c:271
#27 0x00007f25315f5933 in grouping_planner (root=0x7f2532d18c00,
tuple_fraction=<value optimized out>) at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/optimizer/plan/planner.c:1149
#28 0x00007f25315f7409 in subquery_planner (glob=0x7f2532d18b70,
parse=0x7f2532d97180, parent_root=0x7f2532d1d380, hasRecursion=<value
optimized out>, tuple_fraction=<value optimized out>, subroot=<value optimized
out>) at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/optimizer/plan/planner.c:539
#29 0x00007f25315f76f6 in standard_planner (parse=0x7f2532d97180,
cursorOptions=0, boundParams=0x7f2532d970e0) at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/optimizer/plan/planner.c:202
#30 0x00007f2531658bde in pg_plan_query (querytree=0xa0005,
cursorOptions=-362832576, boundParams=0x1) at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/tcop/postgres.c:723
#31 0x00007f2531658cd4 in pg_plan_queries (querytrees=<value optimized out>,
cursorOptions=0, boundParams=0x7f2532d970e0) at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/tcop/postgres.c:782
#32 0x00007f253165949c in exec_bind_message (input_message=<value optimized
out>) at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/tcop/postgres.c:1742
#33 0x00007f253165b275 in PostgresMain (argc=<value optimized out>,
argv=<value optimized out>, username=<value optimized out>) at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/tcop/postgres.c:3968
#34 0x00007f2531619ad3 in BackendRun () at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/postmaster/postmaster.c:3606
#35 BackendStartup () at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/postmaster/postmaster.c:3291
#36 ServerLoop () at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/postmaster/postmaster.c:1455
#37 0x00007f253161c57c in PostmasterMain (argc=851231024, argv=0x7f2532b8c8f0)
at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/postmaster/postmaster.c:1116
#38 0x00007f25315baec3 in main (argc=3, argv=0x7f2532b8c8e0) at
/build/buildd/postgresql-9.1-9.1.3/build/../src/backend/main/main.c:199

--
Jeff Frost <jeff(at)pgexperts(dot)com>
CTO, PostgreSQL Experts, Inc.
Phone: 1-888-PG-EXPRT x506
FAX: 415-762-5122
http://www.pgexperts.com/