Akiban Persistit

Stress tests occasionally fail spectacularly

Bug #1017957 reported by Peter Beaman on 2012-06-26

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	Akiban Persistit	Fix Released	Critical	Peter Beaman	Akiban Persistit 3.1.2

Bug Description

During the past week the 8-hour stress test suite has generated several CorruptVolumeExceptions and other related phenomena. Examples:

Stress6 [main] FAILED: com.persistit.exception.CorruptVolumeException: Volume persistit(/tmp/persistit_tests/persistit) level=0 page=15684 initialPage=57164 key=<{"stress6",98,5,"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"}> walked right more than 50 pages last page visited=81324
        at com.persistit.Exchange.corrupt(Exchange.java:3884)
        at com.persistit.Exchange.searchLevel(Exchange.java:1250)
        at com.persistit.Exchange.searchTree(Exchange.java:1125)
        at com.persistit.Exchange.storeInternal(Exchange.java:1443)
        at com.persistit.Exchange.store(Exchange.java:1294)
        at com.persistit.Exchange.store(Exchange.java:2534)
        at com.persistit.stress.unit.Stress6.executeTest(Stress6.java:98)
        at com.persistit.stress.AbstractStressTest.run(AbstractStressTest.java:93)
        at java.lang.Thread.run(Thread.java:662)

Stress2txn [main] FAILED: com.persistit.exception.RebalanceException
        at com.persistit.Buffer.join(Buffer.java:2523)
        at com.persistit.Exchange.raw_removeKeyRangeInternal(Exchange.java:3367)
        at com.persistit.Exchange.removeKeyRangeInternal(Exchange.java:3070)
        at com.persistit.Exchange.removeInternal(Exchange.java:2999)
        at com.persistit.Exchange.remove(Exchange.java:2927)
        at com.persistit.stress.unit.Stress2txn.executeTest(Stress2txn.java:231)
        at com.persistit.stress.AbstractStressTest.run(AbstractStressTest.java:93)
        at java.lang.Thread.run(Thread.java:662)

Stress2txn [main] FAILED: com.persistit.exception.CorruptVolumeException: LONG_RECORD chain is invalid at page 111919 - invalid page type: Page 111,919 in volume persistit(/tmp/persistit_tests/persistit) at index 1,559 timestamp=909,787,072 status=vr1 type=Data
        at com.persistit.LongRecordHelper.corrupt(LongRecordHelper.java:243)
        at com.persistit.LongRecordHelper.fetchLongRecord(LongRecordHelper.java:103)
        at com.persistit.Exchange.fetchFixupForLongRecords(Exchange.java:2841)
        at com.persistit.Exchange.fetchFromValueInternal(Exchange.java:2778)
        at com.persistit.Exchange.fetchFromBufferInternal(Exchange.java:2747)
        at com.persistit.Exchange.traverse(Exchange.java:2157)
        at com.persistit.Exchange.traverse(Exchange.java:1960)
        at com.persistit.Exchange.traverse(Exchange.java:1897)
        at com.persistit.Exchange.next(Exchange.java:2330)
        at com.persistit.stress.unit.Stress2txn.executeTest(Stress2txn.java:188)
        at com.persistit.stress.AbstractStressTest.run(AbstractStressTest.java:93)
        at java.lang.Thread.run(Thread.java:662)

Related branches

lp:~pbeaman/akiban-persistit/fix_1017957_stress_tests_corruption

Merged into lp:akiban-persistit at revision 329

Nathan Williams: Approve on 2012-06-29

Revision history for this message

Peter Beaman (pbeaman) wrote on 2012-06-26:

We have the broken volume and journal files but they are too large to store in Launchpad.

Peter Beaman (pbeaman) on 2012-06-26

Changed in akiban-persistit:
status:	New → Confirmed
importance:	Undecided → High

Revision history for this message

Peter Beaman (pbeaman) wrote on 2012-06-26:

Download full text (6.3 KiB)

More information. There are four test failures in which a tree appears to be corrupt; we have the volume and journal for each of them. For two of these we can find the root cause of the failures with the integrity checker. Both of these cases are similar and I suspect a common bug mechanism for all four.

In this comment I will paste the details for one of these. The files are currently on donald .../_failed_Mixture3_20120625170544. Mixture3 runs 140 concurrent threads but has no transactions. Thus this failure is unlikely to be related to MVV handling or pruning.

The reported failure during the stress test is:

Stress6 [main] FAILED: com.persistit.exception.CorruptVolumeException: Volume persistit(/tmp/persistit_tests/persistit) level=0 page=15684 initialPage=57164 key=<{"stress6",98,5,"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"}> wal
ked right more than 50 pages last page visited=81324
        at com.persistit.Exchange.corrupt(Exchange.java:3884)
        at com.persistit.Exchange.searchLevel(Exchange.java:1250)
        at com.persistit.Exchange.searchTree(Exchange.java:1125)
        at com.persistit.Exchange.storeInternal(Exchange.java:1443)
        at com.persistit.Exchange.store(Exchange.java:1294)
        at com.persistit.Exchange.store(Exchange.java:2534)
        at com.persistit.stress.unit.Stress6.executeTest(Stress6.java:98)
        at com.persistit.stress.AbstractStressTest.run(AbstractStressTest.java:93)
        at java.lang.Thread.run(Thread.java:662)

This Exception is entirely consistent with the state of the tree detected by IntergrityCheck.

Analysis of the IntegrityCheck follows:

Volume,Tree,Faults,IndexPages,IndexBytes,DataPages,DataBytes,LongRecordPages,LongRecordBytes,MvvPages,MvvRecords,MvvOverhead,MvvAntiValues,IndexHoles,PrunedPages
"persistit","shared",4,34,330100,18394,158695628,0,0,0,0,0,0,853,0
"*","*",4,34,330100,18394,158695628,0,0,0,0,0,0,853,0

(Note: no MVV pages, records or overhead, consistent with there being no transactions in Mixture3.)

Tree persistit:shared Invalid right sibling address in page 81,326 after walking right 719 (path 9,835->110,879->75,079) depth=3

(because index record at page 110,879 offset 740 is bogus. Page 75,079 has a right pointer to 56,164. 57,164 is an empty page.)

Tree persistit:shared left sibling final key is less than parent key (path 9,835->110,879->57,164) depth=3

(same issue)

Tree persistit:shared Invalid right sibling address in page 43,595 after walking right 430 (path 9,835->110,879->57,164) depth=3

(same issue - pointer to page 57,164 is bogus, therefore its right pointer chain is also bogus relative to the index page)

Tree persistit:shared left sibling final key is less than parent key (path 9,835->110,879->56,519) depth=3

(yeah, same thing here, too.)

Tree persistit:shared has 853 unindexed pages

(probably not - report is most likely due to walking pages from 57,164 that aren't really part of the tree)

Relevant sections of interested pages follow:

The index page above all the trouble:

Page 110,879 in volume persistit(./persistit) at index @17,969 status v type Index1
type=2 alloc=4,916 slack=0 keyBlockStart=32 keyBlockEnd=78...

More information.  There are four test failures in which a tree appears to be corrupt; we have the volume and journal for each of them.  For two of these we can find the root cause of the failures with the integrity checker.  Both of these cases are similar and I suspect a common bug mechanism for all four.

In this comment I will paste the details for one of these. The files are currently on donald .../_failed_Mixture3_20120625170544.  Mixture3 runs 140  concurrent threads but has no transactions.  Thus this failure is unlikely to be related to MVV handling or pruning.

The reported failure during the stress test is:

Stress6 [main] FAILED: com.persistit.exception.CorruptVolumeException: Volume persistit(/tmp/persistit_tests/persistit) level=0 page=15684 initialPage=57164 key=<{"stress6",98,5,"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"}> wal
ked right more than 50 pages last page visited=81324
        at com.persistit.Exchange.corrupt(Exchange.java:3884)
        at com.persistit.Exchange.searchLevel(Exchange.java:1250)
        at com.persistit.Exchange.searchTree(Exchange.java:1125)
        at com.persistit.Exchange.storeInternal(Exchange.java:1443)
        at com.persistit.Exchange.store(Exchange.java:1294)
        at com.persistit.Exchange.store(Exchange.java:2534)
        at com.persistit.stress.unit.Stress6.executeTest(Stress6.java:98)
        at com.persistit.stress.AbstractStressTest.run(AbstractStressTest.java:93)
        at java.lang.Thread.run(Thread.java:662)

This Exception is entirely consistent with the state of the tree detected by IntergrityCheck.

Analysis of the IntegrityCheck follows:

(Note: no MVV pages, records or overhead, consistent with there being no transactions in Mixture3.)

Tree persistit:shared Invalid right sibling address in page 81,326 after walking right 719 (path 9,835->110,879->75,079) depth=3

(because index record at page 110,879 offset 740 is bogus.  Page 75,079 has a right pointer to 56,164.  57,164 is an empty page.)

Tree persistit:shared left sibling final key is less than parent key (path 9,835->110,879->57,164) depth=3

(same issue)

Tree persistit:shared Invalid right sibling address in page 43,595 after walking right 430 (path 9,835->110,879->57,164) depth=3

(same issue - pointer to page 57,164 is bogus, therefore its right pointer chain is also bogus relative to the index page)

Tree persistit:shared left sibling final key is less than parent key (path 9,835->110,879->56,519) depth=3

(yeah, same thing here, too.)

Tree persistit:shared has 853 unindexed pages

(probably not - report is most likely due to walking pages from 57,164 that aren't really part of the tree)

Relevant sections of interested pages follow:

The index page above all  the trouble:

Page 110,879 in volume persistit(./persistit) at index @17,969 status v type Index1
  type=2  alloc=4,916  slack=0  keyBlockStart=32  keyBlockEnd=788 timestamp=1,651,694,884 generation=0 right=29,060 hash=175,522
     32: db=128 ebc=  0 tb=14,372 [64]{"stress6",57,1684,"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"}->117,048
     36: db=194 ebc= 14 tb=14,132 [50]{"stress6",57,1730,"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"}->8,975
     40: db=240 ebc= 14 tb=14,012 [50]{"stress6",57,1776,"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"}->20,032
  ...
    732: db=165 ebc= 13 tb=4,976 [52]{"stress6",97,4739,"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"}->5,614
    736: db=166 ebc= 13 tb=4,916 [52]{"stress6",97,4979,"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"}->75,079
    740: db=226 ebc= 10 tb=15,060 [47]{"stress6",98,4,"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"}->57,164
    744: db=159 ebc= 13 tb=15,004 [45]{"stress6",98,31,"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"}->56,519
    748: db= 38 ebc= 12 tb=14,948 [47]{"stress6",98,185,"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"}->93,047
  ...
    780: db=141 ebc= 13 tb=14,500 [46]{"stress6",98,1673,"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"}->61,727
    784: db=142 ebc= 13 tb=14,444 [46]{"stress6",98,1859,"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"}->-1

The data page pointed to by the entry at index 736 - note right pointer correctly matches the entry at 744:

Page 75,079 in volume persistit(./persistit) at index @18,932 status v type Data
  type=1  alloc=13,416  slack=0  keyBlockStart=32  keyBlockEnd=244 timestamp=1,651,807,124 generation=0 right=56,519 hash=205,178
      32: db=128 ebc=  0 tb=14,540 [65]{"stress6",97,4979,"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"}=[1]""
      36: db=244 ebc= 14 tb=14,484 [51]{"stress6",97,4980,"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"}=[1]""

The data page pointed to be the entry at index 744 - note correctly referenced as right sibling of 75,079

Page 56,519 in volume persistit(./persistit) at index @18,934 status v type Data
  type=1  alloc=8,312  slack=0  keyBlockStart=32  keyBlockEnd=652 timestamp=1,651,807,124 generation=0 right=93,047 hash=137,722
      32: db=128 ebc=  0 tb=8,312 [58]{"stress6",98,31,"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"}=[1]""
      36: db=160 ebc= 13 tb=16,332 [45]{"stress6",98,32,"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"}=[1]""
      40: db=161 ebc= 13 tb=16,280 [45]{"stress6",98,33,"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"}=[1]""
      44: db=162 ebc= 13 tb=16,228 [45]{"stress6",98,34,"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"}=[1]""

And the pointer to the following pointer at index 740 is bogus.  Note that the page itself is empty:

Page 57,164 in volume persistit(./persistit) at index @18,147 status v type Data
  type=1  alloc=16,384  slack=0  keyBlockStart=32  keyBlockEnd=32 timestamp=1,651,707,352 generation=0 right=97,218 hash=138,101

And its right sibling has an unrelated left key:

Page 97,218 in volume persistit(./persistit) at index @18,429 status v type Data
  type=1  alloc=9,288  slack=0  keyBlockStart=32  keyBlockEnd=40 timestamp=1,652,388,516 generation=0 right=54,808 hash=17,356
      32: db= 37 ebc=  0 tb=10,304 [2,045]{29,"5555... (a very long key segment)

This analysis still does not tell us how the state because this way, but it narrows the search for the bug mechanism.

Peter Beaman (pbeaman) on 2012-06-28

Changed in akiban-persistit:
importance:	High → Critical

Revision history for this message

Peter Beaman (pbeaman) wrote on 2012-06-29:

We were able to isolate the failure and recreate it in seconds with a new class, Bug1017957Test. With that we were able to find and fix the code paths causing the bug.

Changed in akiban-persistit:
status:	Confirmed → Fix Committed

Nathan Williams (nwilliams) on 2012-06-30

Changed in akiban-persistit:
milestone:	none → 3.1.2
visibility:	private → public
Changed in akiban-persistit:
assignee:	nobody → Peter Beaman (pbeaman)

Peter Beaman (pbeaman) on 2012-06-30

Changed in akiban-persistit:
status:	Fix Committed → Fix Released

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.