Bug #40946 assertion in PageInventoryPage::allocPage in recovery
Submitted: 21 Nov 2008 22:06 Modified: 7 May 2009 16:29
Reporter: Vladislav Vaintroub Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Falcon storage engine Severity:S3 (Non-critical)
Version:6.0.8 OS:Any
Assigned to: Vladislav Vaintroub CPU Architecture:Any
Tags: F_RECOVERY

[21 Nov 2008 22:06] Vladislav Vaintroub
Description:
[Falcon] Error: assertion (!(serialLog->recovering && (serialLog->recoveryPhase ==2))) failed at line 86 in file PageInventoryPage.cpp

This happened on pb2 in falcon_tiny_inserts test on solaris x86. Callstack
 
Error::assertionFailed ()
PageInventoryPage::allocPage (dbb=0x22b1b30,pageType=PAGE_sections, transId=0) at PageInventoryPage.cpp:86
Dbb::allocPage (this=0x22b1b30, pageType=PAGE_sections, transId=0) at Dbb.cpp:249
Section::getSectionPage (dbb=0x22b1b30, root=4, sequence=1, requestedLockType=Exclusive, transId=0) at Section.cpp:273
Section::getSectionPage (this=0x22ad4a0, sequence=1, lockType=Exclusive, transId=0) at Section.cpp:1416
Section::redoRecordLocatorPage (this=0x22ad4a0,  sequence=1018, pageNumber=3048, isPostFlush=true) at Section.cpp:1278
Dbb::redoRecordLocatorPage (this=0x22b1b30, sectionId=0, sequence=1018, pageNumber=3048, isPostFlush=true) at Dbb.cpp:1232
SRLRecordLocator::pass2 (this=0xffbfe420)  at SRLRecordLocator.cpp:86
SerialLog::recover (this=0x21fcf68) at SerialLog.cpp:349
Database::openDatabase (this=0x20a98089,...) Database.cpp:733

Analysis:
- pass2 of recovery should not allocate new pages , realloc is allowed.
This is the assert
- redoRecordLocatorPage calls 
Section::getSectionPage(int sequence, LockType lockType, TransId transId)
   with sequence=1
- page number for the section is looked up in a sparse array sectionPages
int pageNumber = sectionPages.get(sequence);
(section.cpp, line 1398)

- sectionPages is possibly not populated and gives pageNumber 0 back
- another overload of getSectionPage (which could be better named allocSectionPage for clarity) 
Bdb* Section::getSectionPage(Dbb *dbb, int32 root, int32 sequence, LockType requestedLockType, TransId transId)
is called to allocate a new section page

- assertion fails.

How to repeat:
do not know

Suggested fix:
do not know
[28 Jan 2009 7:17] Philip Stoev
Backtrace:

#8  0x00616b10 in Error::assertionFailed (text=0xd35b78 "!(serialLog->recovering && (serialLog->recoveryPhase ==2))",
    fileName=0xd35bb8 "PageInventoryPage.cpp", line=86) at Error.cpp:78
#9  0x006e4a28 in PageInventoryPage::allocPage (dbb=0x24d9b48, pageType=PAGE_sections, transId=0) at PageInventoryPage.cpp:86
#10 0x006917b8 in Dbb::allocPage (this=0x24d9b48, pageType=PAGE_sections, transId=0) at Dbb.cpp:249
#11 0x00723278 in Section::getSectionPage (dbb=0x24d9b48, root=4, sequence=1, requestedLockType=Exclusive, transId=0) at Section.cpp:273
#12 0x0072697c in Section::getSectionPage (this=0x24d52a8, sequence=1, lockType=Exclusive, transId=0) at Section.cpp:1416
#13 0x00726a60 in Section::redoRecordLocatorPage (this=0x24d52a8, sequence=1018, pageNumber=3048, isPostFlush=true) at Section.cpp:1278
#14 0x006944a0 in Dbb::redoRecordLocatorPage (this=0x24d9b48, sectionId=0, sequence=1018, pageNumber=3048, isPostFlush=true) at Dbb.cpp:1204
#15 0x0078ef88 in SRLRecordLocator::pass2 (this=0xffbfe370) at SRLRecordLocator.cpp:86
#16 0x00732624 in SerialLog::recover (this=0x2424e50) at SerialLog.cpp:366
#17 0x0068a904 in Database::openDatabase (this=0x22d1680,
    filename=0xffbfe96c "/export/home/pb2/test/sb_1-254010-1232839794.77/mysql-6.0.10-alpha-solaris10-sparc-test/vardirs/master-data_recovery/falcon_master.fts") at Database.cpp:744
#18 0x0067ae04 in Connection::getDatabase (this=0x24d1638, dbName=0x24d12ac "FALCON_MASTER",
    dbFileName=0xffbfe96c "/export/home/pb2/test/sb_1-254010-1232839794.77/mysql-6.0.10-alpha-solaris10-sparc-test/vardirs/master-data_recovery/falcon_master.fts", threads=0x24d1308) at Connection.cpp:1651
#19 0x0067b0c0 in Connection::openDatabase (this=0x24d1638, dbName=0x24d12ac "FALCON_MASTER", filename=0x24d12dc "falcon_master.fts",
    account=0xd280b8 "mysql", password=0xd280b8 "mysql", address=0x0, parent=0x24d1308) at Connection.cpp:934
#20 0x006251f4 in StorageDatabase::getOpenConnection (this=0x24d11a8) at StorageDatabase.cpp:136
#21 0x006292f4 in StorageHandler::initialize (this=0x22d1068) at StorageHandler.cpp:987
#22 0x00605dcc in StorageInterface::falcon_init (p=0x18db400) at ha_falcon.cpp:245
#23 0x00450014 in ha_initialize_handlerton (plugin=0x1a98a10) at handler.cc:441
#24 0x0053d94c in plugin_initialize (plugin=0x1a98a10) at sql_plugin.cc:1007
#25 0x00546644 in plugin_init (argc=0xf637ec, argv=0x19c42f8, flags=0) at sql_plugin.cc:1216
#26 0x002a6b9c in init_server_components () at mysqld.cc:4125
#27 0x002ad820 in main (argc=11, argv=0xffbff2c4) at mysqld.cc:4636
[28 Jan 2009 11:01] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/64255

2981 Vladislav Vaintroub	2009-01-28
      Bug #40946: assertion in PageInventoryPage::allocPage in recovery.
      
      Reason : 
      Creation of section pages was not always logged. Hence, not all section pages were redone by recovery. During recovery a section root was missing and Section::getSectionPage was trying to allocate a missing root. This caused the assertion in bug.
      
      Solution : always log section pages and rebuild them on recovery.
      - This patch also simplified the redo logic for section pages - no more guessing and trying to save information in it. The page should be clean after creation. 
      
      - This patch also removed another "allocate on demand" code in getSectionRoot()  - it should not be necessary since the page is either already  in the tablespace (written by last checkpoint), or exists as in log record and will be created  in recovery prior to first use.
[2 Feb 2009 11:58] Olav Sandstå
Re-opens the bug since this assert still seems to happen. Have seen it twice in runs of falcon_tiny_insert:

# 22:10:11 Recovery phase 2...
# 22:10:11 [Falcon] Error: assertion (!(serialLog->recovering && (serialLog->recoveryPhase ==2))) failed at line 91 in file PageInventoryPage.cpp
[2 Feb 2009 12:09] Olav Sandstå
Here is the call stack for the failing assert:

(dbx) where
  [1] _thrp_exit(0x6, 0xc99950, 0x437f8, 0xfef181d0, 0xfef6c380, 0x189e478), at 0xfef411e4 
=>[2] handle_segfault(sig = 6), line 2679 in "mysqld.cc"
  [3] tdb_sync_obj_deregister(0x6, 0x0, 0xffbfd638, 0x2a0cd8, 0x0, 0x0), at 0xfef4011c 
  [4] _pthread_create(0x6, 0x0, 0x12, 0x0, 0xff052000, 0xffbfd638), at 0xfef35214 
  [5] nss_pack_key2str(0x6, 0xd28118, 0xffbfda08, 0xff052000, 0xfef6c388, 0x4), at 0xfeedfdd8 
  [6] Error::debugBreak(), line 94 in "Error.cpp"
  [7] Error::error(string = 0xd28128 "assertion (%s) failed at line %d in file %s\n", ..., ...), line 71 in "Error.cpp"
  [8] Error::assertionFailed(text = 0xd36248 "!(serialLog->recovering && (serialLog->recoveryPhase ==2))", fileName = 0xd36288 "PageInventoryPage.cpp", line = 91), line 78 in "Error.cpp"
  [9] PageInventoryPage::allocPage(dbb = 0x24dbb30, pageType = PAGE_sections, transId = 0), line 91 in "PageInventoryPage.cpp"
  [10] Dbb::allocPage(this = 0x24dbb30, pageType = PAGE_sections, transId = 0), line 254 in "Dbb.cpp"
  [11] Section::getSectionPage(dbb = 0x24dbb30, root = 4, sequence = 1, requestedLockType = Exclusive, transId = 0), line 282 in "Section.cpp"
  [12] Section::getSectionPage(this = 0x24d7290, sequence = 1, lockType = Exclusive, transId = 0), line 1393 in "Section.cpp"
  [13] Section::redoRecordLocatorPage(this = 0x24d7290, sequence = 1018, pageNumber = 3051, isPostFlush = true), line 1255 in "Section.cpp"
  [14] Dbb::redoRecordLocatorPage(this = 0x24dbb30, sectionId = 0, sequence = 1018, pageNumber = 3051, isPostFlush = true), line 1209 in "Dbb.cpp"
  [15] SRLRecordLocator::pass2(this = 0xffbfe358), line 86 in "SRLRecordLocator.cpp"
  [16] SerialLog::recover(this = 0x2426e50), line 366 in "SerialLog.cpp"
  [17] Database::openDatabase(this = 0x22d3680, filename = 0xffbfe96c "/export/home/pb2/test/sb_1-279503-1233348555.83/mysql-6.0.10-alpha-solaris10-sparc-test/vardirs/master-data_recovery/falcon_master.fts"), line 751 in "Database.cpp"
  [18] Connection::getDatabase(this = 0x24d3630, dbName = 0x24d32a4 "FALCON_MASTER", dbFileName = 0xffbfe96c "/export/home/pb2/test/sb_1-279503-1233348555.83/mysql-6.0.10-alpha-solaris10-sparc-test/vardirs/master-data_recovery/falcon_master.fts", threads = 0x24d3300), line 1650 in "Connection.cpp"
  [19] Connection::openDatabase(this = 0x24d3630, dbName = 0x24d32a4 "FALCON_MASTER", filename = 0x24d32d4 "falcon_master.fts", account = 0xd28758 "mysql", password = 0xd28758 "mysql", address = (nil), parent = 0x24d3300), line 933 in "Connection.cpp"
  [20] StorageDatabase::getOpenConnection(this = 0x24d31a0), line 136 in "StorageDatabase.cpp"
  [21] StorageHandler::initialize(this = 0x22d3068), line 987 in "StorageHandler.cpp"
  [22] StorageInterface::falcon_init(p = 0x18dd400), line 245 in "ha_falcon.cpp"
  [23] ha_initialize_handlerton(plugin = 0x1a9aa10), line 441 in "handler.cc"
  [24] plugin_initialize(plugin = 0x1a9aa10), line 1007 in "sql_plugin.cc"
  [25] plugin_init(argc = 0xf6410c, argv = 0x19c62f8, flags = 0), line 1216 in "sql_plugin.cc"
  [26] init_server_components(), line 4125 in "mysqld.cc"
  [27] main(argc = 11, argv = 0xffbff2c4), line 4636 in "mysqld.cc"
[2 Feb 2009 17:31] Kevin Lewis
Olav, open indicates it is not verified.  It is probably better to put patch pending back to in progress or verified
[3 Feb 2009 19:38] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/65045

2998 Vladislav Vaintroub	2009-02-03
      Bug #40946: assertion in PageInventoryPage::allocPage in recovery.
            
      Reason : 
      Creation of section pages was still not always logged, even after the 
      previous patch.During recovery, section page is not recreated and 
      Falcon asserts when new page must be allocated (recovery does not
      tolarate new pages allocations during this phase)
      
      Solution:
      When section page is created, always create serial log entry log. 
      For this purpose, creation and logging are factored out into separate 
      function allocSectionPage().
[4 Feb 2009 5:14] Kevin Lewis
Reviewed new patch, OK to push.
[13 Feb 2009 7:24] Bugs System
Pushed into 6.0.10-alpha (revid:alik@sun.com-20090211182317-uagkyj01fk30p1f8) (version source revid:vvaintroub@mysql.com-20090204093352-y60x831o5etl2mqu) (merge vers: 6.0.10-alpha) (pib:6)
[7 May 2009 16:29] MC Brown
Internal/test fix. No changelog entry required.