Re: Hanging backends and possible index corruption

On 2013-01-25 16:24:52 +0100, Bernd Helmle wrote:
> We are currently analyzing an issue at one of our customers PostgreSQL
> database.
> 
> The current version is 9.1.6 (update to 9.1.7 is scheduled for next monday,
> no downtime possible before). It runs on POWER7 (pSeries 740) on an RHEL6.3
> 64-bit LPAR. The packages are built from PGDG SVN sources, no special tweaks
> added. We saw no hardware related errors on this machine, nor any crashes.
> 
> What currently happens on this machine are hanging statements (SELECTs and
> INSERTs occasionally) with 100% CPU. After some investigation it turned out
> that the corresponding backends are seeking within an index file over and
> over again in a loop. Looking into the hanging queries i've recognized
> certain keys which seems to have the problem, other keys used in the WHERE
> condition run smoothly. Turning off index and bitmap index scans caused the
> suspicious keys to return results, too.
> 
> So i've saved the index file (normal BTree index with a single bigint
> column), did a REINDEX and the problem was gone. Looking at the index file
> with pg_filedump and pgbtreecheck from Alvaro gave me the following output:
> 
> pgbtreecheck gives warnings about pages' parents and then loops visiting the
> same pages over and over again:
> 
> NOTICE: fast root: block 290 at level 2
> NOTICE: setting page parents
> WARNING: block 12709 already had a parent (8840); new parent is 12177
> WARNING: block 12710 already had a parent (12439); new parent is 10835
> NOTICE: done setting parents
> NOTICE: Checking forward scan of level 0, starting at block 1
> 
> -- loop starts
> 
> WARNING: right sibling 12710 does not point left to me (11680); points to
> 10924 instead
> 
> Looking into the relevant pages and their prev and next pointers give me the
> following:
> 
> pg_filedump -i -R 11680 ~/tmp/100252789 | grep Blocks
>  Blocks: Previous (12651)  Next (12710)  Level (0)  CycleId (0)
> 
> pg_filedump -i -R 10924 ~/tmp/100252789 | grep Blocks
>  Blocks: Previous (10923)  Next (12710)  Level (0)  CycleId (0)
> 
> pg_filedump -i -R 12710 ~/tmp/100252789 | grep Blocks
>  Blocks: Previous (10924)  Next (10925)  Level (0)  CycleId (0)
> 
> pg_filedump -i -R 10925 ~/tmp/100252789 | grep Blocks
>  Blocks: Previous (12710)  Next (10926)  Level (0)  CycleId (0)
> 
> pg_filedump -i -R 12709 ~/tmp/100252789 | grep Blocks
>  Blocks: Previous (8849)  Next (8850)  Level (0)  CycleId (0)
> 
> pg_filedump -i -R 8840 ~/tmp/100252789 | grep Blocks
>  Blocks: Previous (8555)  Next (9125)  Level (1)  CycleId (0)
> 
> pg_filedump -i -R 12439 ~/tmp/100252789 | grep Blocks
>  Blocks: Previous (11405)  Next (11690)  Level (1)  CycleId (0)
> 
> $ pg_filedump -i -R 12177 ~/tmp/100252789 | grep Blocks
>  Blocks: Previous (11690)  Next (0)  Level (1)  CycleId (0)
> 
> $ pg_filedump -i -R 10835 ~/tmp/100252789 | grep Blocks
>  Blocks: Previous (10550)  Next (11120)  Level (1)  CycleId (0)
> 
> This symptom happened three times in the last couple of weeks now. Looking
> at the numbers doesn't give me the impression that some flaky hardware could
> be involved. What else can we do to track down this problem, any
> suggestions?

Did you reindex after upgrading to 9.1.6? Did you ever have any crashes
or failovers before upgrading to 9.1.6?
I have seen pretty similar symptoms caused by "Fix persistence marking
of shared buffers during WAL replay" in 9.1.6.

Greetings,

Andres Freund

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