Re: hung backends stuck in spinlock heavy endless loop

Hi,

> The plot thickens!  I looped the test, still stock 9.4 as of this time
> and went to lunch. When I came back, the database was in recovery
> mode.  Here is the rough sequence of events.
>

Whoa. That looks scary. Did you see (some of) those errors before? Most
of them should have been emitted independently of being built with
assertions.

> 1) REINDEXED pg_class (wanted clean slate for full reproduction)
> 2) before too long (unfortunately did not configure timestamps in the
> log) starting seeing:
> 
> ERROR:  root page 3 of index "pg_class_oid_index" has level 0,
> expected 1 at character 8
> QUERY:  UPDATE CDSRunTable SET
>           Finished = clock_timestamp(),
>           DidSucceed = _DidSucceed,
>           ErrorMessage = _ErrorMessage
>         WHERE CDSRunTableId = _CdsRunTableId
> CONTEXT:  PL/pgSQL function cdsreconcileruntable(bigint) line 82 at
> SQL statement
> STATEMENT:  SELECT CDSReconcileRunTable(2020)
> 
> ..and again with a FATAL
> FATAL:  root page 3 of index "pg_class_oid_index" has level 0, expected 1
> ERROR:  root page 3 of index "pg_class_oid_index" has level 0, expected 1
> CONTEXT:  SQL statement "UPDATE CDSRunTable SET
>           Finished = clock_timestamp(),
>           DidSucceed = _DidSucceed,
>           ErrorMessage = _ErrorMessage
>         WHERE CDSRunTableId = _CdsRunTableId"
>     PL/pgSQL function cdsreconcileruntable(bigint) line 82 at SQL statement

Just to be absolutely clear, those happened *before* the following
errors? And there were no 'during exception cleanup' like errors before?

> 3) shortly (?) after that, I got:
> 
> WARNING:  did not find subXID 14955 in MyProc
> CONTEXT:  PL/pgSQL function cdsreconcileruntable(bigint) line 35
> during exception cleanup
> WARNING:  you don't own a lock of type RowExclusiveLock
> CONTEXT:  PL/pgSQL function cdsreconcileruntable(bigint) line 35
> during exception cleanup
> LOG:  could not send data to client: Broken pipe
> CONTEXT:  PL/pgSQL function cdsreconcileruntable(bigint) line 35
> during exception cleanup
> STATEMENT:  SELECT CDSReconcileRunTable(2151)
> WARNING:  ReleaseLockIfHeld: failed??
> CONTEXT:  PL/pgSQL function cdsreconcileruntable(bigint) line 35
> during exception cleanup
> ERROR:  failed to re-find shared proclock object
> CONTEXT:  PL/pgSQL function cdsreconcileruntable(bigint) line 35
> during exception cleanup
> STATEMENT:  SELECT CDSReconcileRunTable(2151)
> WARNING:  AbortSubTransaction while in ABORT state
> WARNING:  did not find subXID 14955 in MyProc
> WARNING:  you don't own a lock of type AccessShareLock
> WARNING:  ReleaseLockIfHeld: failed??
> ERROR:  failed to re-find shared proclock object
> WARNING:  AbortSubTransaction while in ABORT state
> WARNING:  did not find subXID 14955 in MyProc
> WARNING:  you don't own a lock of type AccessShareLock
> WARNING:  ReleaseLockIfHeld: failed??
> WARNING:  you don't own a lock of type ShareLock
> TRAP: FailedAssertion("!(FastPathStrongRelationLocks->count[fasthashcode]
> > 0)", File: "lock.c", Line: 1240)
> LOG:  server process (PID 10117) was terminated by signal 6: Aborted
> LOG:  terminating any other active server processes

Ick.

Were there any 'LOG: Handling deadlock detected on CdsRunTableId' log
entries before? It's hard to know from here, but the 'during exception
cleanup' indicates a problem in abort handling.  Were there any deadlock
detected errors closeby?

You're catching deadlock errors in a subtransaction. Hm.

Greetings,

Andres Freund

-- Andres Freund                       http://www.2ndQuadrant.com/PostgreSQL Development, 24x7 Support, Training &
Services