Bug #42560 Falcon recovery error: page 411048/1 wrong page type, expected 5 got 7
Submitted: 2 Feb 2009 21:58 Modified: 15 May 2009 15:56
Reporter: Olav Sandstå Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Falcon storage engine Severity:S2 (Serious)
Version:6.0.10-alpha OS:Any
Assigned to: Vladislav Vaintroub
Tags: F_RECOVERY
Triage: Triaged: D2 (Serious)

[2 Feb 2009 21:58] Olav Sandstå
Description:
During recovery of a fairly large table containing about 2 million records, Falcon hits the following assert after about 10-15 minutes:

New table space FALCON_USER, id 1, type 0, filename falcon_user.fts
New table space FALCON_TEMPORARY, id 2, type 0, filename falcon_temporary.fts
[Falcon] Error: page 411048/1 wrong page type, expected 5 got 7

Call stack from the core file:

  [12] Error::error(string = 0x15c913f "page %d/%d wrong page type, expected %d got %d\n", ...), line 71 in "Error.cpp"
  [13] Cache::fetchPage(this = 0x1eb5620, dbb = 0x1eb9b20, pageNumber = 411048, pageType = PAGE_btree, lockType = Exclusive), line 322 in "Cache.cpp"
  [14] Dbb::fetchPage(this = 0x1eb9b20, pageNumber = 411048, pageType = PAGE_btree, lockType = Exclusive), line 226 in "Dbb.cpp"
  [15] Dbb::handoffPage(this = 0x1eb9b20, bdb = 0x4faab28, pageNumber = 411048, pageType = PAGE_btree, lockType = Exclusive), line 275 in "Dbb.cpp"
  [16] IndexRootPage::findInsertionLeaf(dbb = 0x1eb9b20, indexId = 1, indexKey = 0xfffffd7fffdf0500, recordNumber = 1500237, transId = 0), line 311 in "IndexRootPage.cpp"
  [17] IndexRootPage::addIndexEntry(dbb = 0x1eb9b20, indexId = 1, key = 0xfffffd7fffdfaf90, recordNumber = 1500237, transId = 0), line 133 in "IndexRootPage.cpp"
  [18] IndexRootPage::indexMerge(dbb = 0x1eb9b20, indexId = 1, logRecord = 0xfffffd7fffdfe360, transId = 0), line 1009 in "IndexRootPage.cpp"
  [19] SRLUpdateIndex::execute(this = 0xfffffd7fffdfe360), line 217 in "SRLUpdateIndex.cpp"
  [20] SRLUpdateIndex::redo(this = 0xfffffd7fffdfe360), line 187 in "SRLUpdateIndex.cpp"
  [21] SerialLog::recover(this = 0x1e250f0), line 403 in "SerialLog.cpp"
  [22] Database::openDatabase(this = 0x1c801b8, filename = 0xfffffd7fffdfe8dc "/export/home/tmp/mysqldb/falcon_master.fts"), line 751 in "Database.cpp"
  [23] Connection::getDatabase(this = 0x1eb4d90, dbName = 0x1eb4a04 "FALCON_MASTER", dbFileName = 0xfffffd7fffdfe8dc "/export/home/tmp/mysqldb/falcon_master.fts", threads = 0x1eb4a70), line 1650 in "Connection.cpp"
  [24] Connection::openDatabase(this = 0x1eb4d90, dbName = 0x1eb4a04 "FALCON_MASTER", filename = 0x1eb4a3c "falcon_master.fts", account = 0x15c2f4f "mysql", password = 0x15c2f55 "mysql", address = (nil), parent = 0x1eb4a70), line 933 in "Connection.cpp"
  [25] StorageDatabase::getOpenConnection(this = 0x1eb4890), line 136 in "StorageDatabase.cpp"
  [26] StorageHandler::initialize(this = 0x1c7f668), line 987 in "StorageHandler.cpp"
  [27] StorageInterface::falcon_init(p = 0x1c012d0), line 245 in "ha_falcon.cpp"
  [28] ha_initialize_handlerton(plugin = 0x21b2e58), line 441 in "handler.cc"
  [29] plugin_initialize(plugin = 0x21b2e58), line 1007 in "sql_plugin.cc"
  [30] plugin_init(argc = 0x18eed58, argv = 0x1c00388, flags = 0), line 1216 in "sql_plugin.cc"
  [31] init_server_components(), line 4125 in "mysqld.cc"
  [32] main(argc = 12, argv = 0xfffffd7fffdff3a8), line 4636 in "mysqld.cc"

How to repeat:
I have seen this crash only once. What I did at that time was to:

1. Start Falcon. I used the following configuration for Falcon:

--falcon_page_cache_size=500M --falcon_record_memory_max=1000M --falcon_serial_log_dir=/export/home2/tmp/mysql-log/falcon --falcon-debug-mask=2

2. Run a Java client that do the following:

a: Creates a simple table like this:

    CREATE TABLE TESTDATA (priKey int NOT NULL,data VARCHAR(1000), PRIMARY KEY(priKey)) ENGINE=Falcon

b. Inserts records of about 1000 byte into this table.

c. Commits once for every 100.000 inserted records.

3. After about 2.000.000 records was inserted I did a:

    kill -9 ....

4. Falcon get restarted by mysqld_safe

5. Wait for about 10-15 minutes until the assert was hit.

Suggested fix:
Recovery should not fail (and if it fails it better do it immediately instead of waiting for 15 minutes :-) )
[2 Feb 2009 22:11] Olav Sandstå
Java client that was used for generating load on the database

Attachment: LoadData.java (text/x-java), 4.49 KiB.

[2 Feb 2009 23:34] Miguel Solorzano
c:\dbs>c:\dbs\6.0\bin\mysqld --defaults-file=c:\dbs\6.0\my.ini --standalone --console
SSL error: Unable to get certificate from 'C:/dbs/5.0/server-cert.pem'
090202 21:31:37 [Warning] Failed to setup SSL
090202 21:31:38  InnoDB: Started; log sequence number 0 48155
[Falcon] Error: assertion (!(serialLog->recovering && (serialLog->recoveryPhase ==2))) failed at line 86 in file .\Pa

090202 21:32:55 - mysqld got exception 0x80000003 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help diagnose
the problem, but since we have already crashed, something is definitely wrong
and this may fail.

key_buffer_size=8384512
read_buffer_size=131072
max_used_connections=0
max_threads=151
thread_count=0
connection_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 338230 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
00000001407AC43A    mysqld.exe!Error::debugBreak()[error.cpp:92]
00000001407AC308    mysqld.exe!Error::error()[error.cpp:73]
00000001407AC3F8    mysqld.exe!Error::assertionFailed()[error.cpp:79]
00000001408B1EBB    mysqld.exe!PageInventoryPage::allocPage()[pageinventorypage.cpp:86]
000000014084497F    mysqld.exe!Dbb::allocPage()[dbb.cpp:249]
000000014084D9F4    mysqld.exe!Section::getSectionPage()[section.cpp:273]
0000000140851CEB    mysqld.exe!Section::getSectionPage()[section.cpp:1416]
00000001408516A8    mysqld.exe!Section::redoRecordLocatorPage()[section.cpp:1278]
0000000140847B0D    mysqld.exe!Dbb::redoRecordLocatorPage()[dbb.cpp:1233]
00000001408BE4CB    mysqld.exe!SRLRecordLocator::pass2()[srlrecordlocator.cpp:87]
0000000140875BD1    mysqld.exe!SerialLog::recover()[seriallog.cpp:351]
00000001407ED2F2    mysqld.exe!Database::openDatabase()[database.cpp:733]
00000001407CC20B    mysqld.exe!Connection::getDatabase()[connection.cpp:1652]
00000001407C9624    mysqld.exe!Connection::openDatabase()[connection.cpp:934]
00000001407C1739    mysqld.exe!StorageDatabase::getOpenConnection()[storagedatabase.cpp:137]
00000001407AAFCE    mysqld.exe!StorageHandler::initialize()[storagehandler.cpp:986]
0000000140799A7B    mysqld.exe!StorageInterface::falcon_init()[ha_falcon.cpp:245]
00000001400805FF    mysqld.exe!ha_initialize_handlerton()[handler.cc:450]
0000000140339CAC    mysqld.exe!plugin_initialize()[sql_plugin.cc:1007]
0000000140339ACD    mysqld.exe!plugin_init()[sql_plugin.cc:1216]
00000001401CC8FB    mysqld.exe!init_server_components()[mysqld.cc:4130]
00000001401CA549    mysqld.exe!win_main()[mysqld.cc:4639]
00000001401CD624    mysqld.exe!mysql_service()[mysqld.cc:4803]
00000001401CDA8E    mysqld.exe!main()[mysqld.cc:4976]
00000001409DDF9C    mysqld.exe!__tmainCRTStartup()[crt0.c:327]
00000001409DDD6E    mysqld.exe!mainCRTStartup()[crt0.c:196]
000000007763495D    kernel32.dll!BaseThreadInitThunk()
0000000077768791    ntdll.dll!RtlUserThreadStart()
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
[2 Feb 2009 23:37] Miguel Solorzano
Thank you for the bug report.
[9 Feb 2009 14:54] Philip Stoev
To reproduce, clone from the mysql-test-extra-6.0 tree and then

$ cd mysql-test-extra-6.0/test-extra/gentest
$ perl pb2gentest.pl /build/bzr/6.0-falcon-team /tmp/varidr aa falcon_ddl
[10 Feb 2009 19:13] 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/65789

3010 Vladislav Vaintroub	2009-02-10
      Bug #42560 Falcon recovery error:  wrong page type, 
      expected 5 got <something>
      
      Problem:
      during index creation root page number is not logged. 
      The page is not recreated on recovery which may result 
      in corrupted index.
      
      
      Fix:
      - Log index root page number and recreate index root
      page in recovery of SRLCreateIndex. Do it in phase 2
      of recovery, instead of "redo" phase.
      (phase2 is responsible for recreating "physical" objects
      , e.g pages)
      
      
      - Log index root page number when creating index and 
      recreate this page on recovery. Refactor code so 
      createIndexRoot can be called inside and outside recovery.
      The code is more compact and better readable.
      
      -  Simplify redoIndexPage.
      Do not care about left and right neighbour pages.
      they are logged separately during splits, and there is no 
      need for careful trialReads.
      
      - Cleanup: 
       remove misleadingly named  IndexPage::createNewLevel(), 
         substitute with initRootPage().
      
       remove setIndexRoot(), its single usage was within 
       redoDeleteIndex()
[10 Feb 2009 21:39] 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/65810

3010 Vladislav Vaintroub	2009-02-10
      Bug #42560 Falcon recovery error:  wrong page type, 
      expected 5 got <something>
      
      Problem:
      during index creation root page number is not logged. 
      The page is not recreated on recovery which may result 
      in corrupted index.
      
      
      Fix:
      - Log index root page number and recreate index root
      page in recovery of SRLCreateIndex. Do it in phase 2
      of recovery, instead of "redo" phase.
      (phase2 is responsible for recreating "physical" objects
      , e.g pages)
      
      
      - Log index root page number when creating index and 
      recreate this page on recovery. Refactor code so 
      createIndexRoot can be called inside and outside recovery.
      The code is more compact and better readable.
      
      -  Simplify redoIndexPage.
      Do not care about left and right neighbour pages.
      they are logged separately during splits, and there is no 
      need for careful trialReads.
      
      - Cleanup: 
       remove misleadingly named  IndexPage::createNewLevel(), 
         substitute with initRootPage().
      
       remove setIndexRoot(), its single usage was within 
       redoDeleteIndex()
[10 Feb 2009 21:40] 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/65812

3010 Vladislav Vaintroub	2009-02-10
      Bug #42560 Falcon recovery error:  wrong page type, 
      expected 5 got <something>
      
      Problem:
      during index creation root page number is not logged. 
      The page is not recreated on recovery which may result 
      in corrupted index.
      
      
      Fix:
      - Log index root page number and recreate index root
      page in recovery of SRLCreateIndex. Do it in phase 2
      of recovery, instead of "redo" phase.
      (phase2 is responsible for recreating "physical" objects
      , e.g pages)
      
      
      - Log index root page number when creating index and 
      recreate this page on recovery. Refactor code so 
      createIndexRoot can be called inside and outside recovery.
      The code is more compact and better readable.
      
      -  Simplify redoIndexPage.
      Do not care about left and right neighbour pages.
      they are logged separately during splits, and there is no 
      need for careful trialReads.
      
      - Cleanup: 
       remove misleadingly named  IndexPage::createNewLevel(), 
         substitute with initRootPage().
      
       remove setIndexRoot(), its single usage was within 
       redoDeleteIndex()
[10 Feb 2009 22:51] 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/65824

3010 Vladislav Vaintroub	2009-02-10
      Bug #42560 Falcon recovery error:  wrong page type, 
      expected 5 got <something>
      
      Problem:
      during index creation root page number is not logged. 
      The page is not recreated on recovery which may result 
      in corrupted index.
      
      
      Fix:
      - Log index root page number and recreate index root
      page in recovery of SRLCreateIndex. Do it in phase 2
      of recovery, instead of "redo" phase.
      (phase2 is responsible for recreating "physical" objects
      , e.g pages)
      
      - Also, SRLDeleteIndex will be executed in phase 2 of recovery
      
      - Log index root page number when creating index and 
      recreate this page on recovery. Refactor code so 
      createIndexRoot can be called inside and outside recovery.
      The code is more compact and better readable.
      
      -  Simplify redoIndexPage.
      Do not care about left and right neighbour pages.
      they are logged separately during splits, and there is no 
      need for careful trialReads.
      
      - Cleanup: 
       remove misleadingly named  IndexPage::createNewLevel(), 
         substitute with initRootPage().
      
       remove setIndexRoot(), its single usage was within 
       redoDeleteIndex()
[11 Feb 2009 17:18] Kevin Lewis
Change looks good to me.  

In addition, Jim Starkey made these comments via email;
-------------------------------
While I heartedly applaud refactoring, combining refactoring with semantic change is rather difficult to follow.  It would be easier to follow if the refactor were pushed as a separate change.

That aside, it looks fine.  Including the root index page number in SRLCreateIndex is completely sound (I wonder why I didn't do it in the first place?), as is always recreating the root page during redo of SRLCreateIndex.  I also agree that this requires moving the re-creation from phase 3 to phase 2 of recovery.  And I'm complete OK with the refactoring.

As for the details, it's hard to follow given the size of change.  But it's theoretically sound and I have no doubt that Vlad will test it and fix any cases that might have slipped through the cracks. 
-------------------------------
[2 Mar 2009 14:12] Bugs System
Pushed into 6.0.11-alpha (revid:alik@sun.com-20090302140208-lfdejjbcyezlhhjt) (version source revid:vvaintroub@mysql.com-20090210225004-d09yy9inre0laepg) (merge vers: 6.0.10-alpha) (pib:6)
[15 May 2009 15:56] MC Brown
A note has been added to the 6.0.11 changelog: 

Recovery of a Falcon table with a large number of rows can cause a failure in the page type written for the internal FALCON_USER and FALCON_TEMPORARY tablespaces.