Bug #44162 Falcon recovery error DataPage::computeSpaceAvailable got a negative number
Submitted: 8 Apr 2009 17:36 Modified: 28 Jul 2009 14:59
Reporter: Philip Stoev Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server: Falcon storage engine Severity:S1 (Critical)
Version:6.0-falcon-team OS:Any
Assigned to: Ann Harrison CPU Architecture:Any
Tags: F_RECOVERY

[8 Apr 2009 17:36] Philip Stoev
Description:
Vlad noticed this bug and Ann agreed to take it. During recovery from the falcon_many_indexes RQG test, Falcon reported the following:

 00:38:26 DataPage::computeSpaceAvailable got a negative number
# 00:38:26 Data page 1241579777, max line 31093
# 00:38:26     0. offset 29548, length 29548
# 00:38:26     1. offset 29537, length 29537
# 00:38:26     2. offset 29793, length 29793
...
# 00:38:27     31090. offset 58785, length -24163
# 00:38:27     31091. offset 40421, length -6751
# 00:38:27     31092. offset 41373, length -25115
# 00:38:47 [Falcon] Error: IO::writePages(): corrupted page 3198 (pageNumber = 1241579777, pageType = -1)
# 00:38:47 Log message '[Falcon] Error: IO::writePages(): corrupted page 3198 (pageNumber = 1241579777, pageType = -1)' indicates database corruption
# 00:38:47 Bugcheck: IO::writePages(): corrupted page 3198 (pageNumber = 1241579777, pageType = -1)
# 00:38:47 Log message 'Bugcheck: IO::writePages(): corrupted page 3198 (pageNumber = 1241579777, pageType = -1)' indicates database corruption
# 00:38:47 090408  0:38:47 - mysqld got signal 6 ;
# 00:38:47 Recovery has apparently crashed.
# 00:38:47 This could be because you hit a bug. It is also possible that this binary
# 00:38:47 or one of the libraries it was linked against is corrupt, improperly built,
# 00:38:47 Log message 'or one of the libraries it was linked against is corrupt, improperly built,' indicates database corruption
# 00:38:47 or misconfigured. This error can also be caused by malfunctioning hardware.
# 00:38:47 We will try our best to scrape up some info that will hopefully help diagnose
# 00:38:47 the problem, but since we have already crashed, something is definitely wrong
# 00:38:47 and this may fail.
# 00:38:47 
# 00:38:47 key_buffer_size=8384512
# 00:38:47 read_buffer_size=131072
# 00:38:47 max_used_connections=0
# 00:38:47 max_threads=151
# 00:38:47 thread_count=0
# 00:38:47 connection_count=0
# 00:38:47 It is possible that mysqld could use up to 
# 00:38:47 key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 337825 K
# 00:38:47 bytes of memory
# 00:38:47 Hope that's ok; if not, decrease some variables in the equation.
# 00:38:47 
# 00:38:47 thd: 0x0
# 00:38:47 Attempting backtrace. You can use the following information to find out
# 00:38:47 where mysqld died. If you see no messages after this, something went
# 00:38:47 terribly wrong...
# 00:38:47 stack_bottom = (nil) thread_stack 0x30c00
mysqld(my_print_stacktrace+0x32) [0x882f335]
mysqld(handle_segfault+0x2cd) [0x82c00fd]
# 00:38:47 Recovery has apparently crashed.
# 00:38:47 [0x62b420]
mysqld(Error::debugBreak()+0x12) [0x855e5a4]
mysqld(Error::error(char const*, ...)+0x7a) [0x855e620]
mysqld(IO::writePages(int, int, unsigned char const*, int)+0x11f) [0x85ca9c7]
mysqld(IO::writePage(Bdb*, int)+0xf6) [0x85cace8]
mysqld(Cache::writePage(Bdb*, int)+0x114) [0x864eb0a]
mysqld(Cache::findBuffer(Dbb*, int, LockType)+0xfc) [0x864efb8]
mysqld(Cache::fakePage(Dbb*, int, PageType, unsigned int)+0x14b) [0x864f46b]
mysqld(Dbb::fakePage(int, PageType, unsigned int)+0x48) [0x85b93f2]
mysqld(PageInventoryPage::allocPage(Dbb*, PageType, unsigned int)+0x1dc) [0x85ef54a]
mysqld(Dbb::allocPage(PageType, unsigned int)+0x1f) [0x85b90ef]
mysqld(Section::storeTail(Stream*, int, int*, unsigned int, bool)+0x88) [0x861bc5a]
mysqld(DataPage::updateRecord(Section*, int, Stream*, unsigned int, bool)+0x295) [0x8653c69]
mysqld(Section::updateRecord(int, Stream*, unsigned int, bool)+0x3eb) [0x861dc61]
mysqld(Dbb::updateRecord(int, int, Stream*, unsigned int, bool)+0x49) [0x85bb801]
mysqld(SRLUpdateRecords::redo()+0x2a8) [0x8615698]
mysqld(SerialLog::recover()+0xc13) [0x8625d93]
mysqld(Database::openDatabase(char const*)+0x341) [0x85b1997]
mysqld(Connection::getDatabase(char const*, char const*, Threads*)+0x149) [0x85a3f75]
mysqld(Connection::openDatabase(char const*, char const*, char const*, char const*, char const*, Threads*)+0x198) [0x85a5492]
mysqld(StorageDatabase::getOpenConnection()+0x86) [0x8569328]
mysqld(StorageHandler::initialize()+0x9f) [0x856b9d5]
mysqld(StorageInterface::falcon_init(void*)+0x256) [0x855bfaa]
mysqld(ha_initialize_handlerton(st_plugin_int*)+0xa3) [0x8408c3f]
mysqld [0x84bf646]
mysqld(plugin_init(int*, char**, int)+0x695) [0x84c0b9b]
mysqld [0x82c2d8f]
mysqld(main+0x1de) [0x82c3d48]

How to repeat:
The tablespace will be uploaded shortly.
[8 Apr 2009 17:44] Philip Stoev
Tablespace before recovery - in the master-data directory

http://mysql-systemqa.s3.amazonaws.com/bug44162-vardir.tar.gz

Note the very high compression ration 6MB -> 300MB.
[1 Jul 2009 20:06] Ann Harrison
Although I could reproduce this a week ago, the most
recent pull works correctly.  Recovery succeeds
and after recovery the tables appear correct.
[28 Jul 2009 14:59] Ann Harrison
This was a bug, but a change made for another bug fixed
this one.  The code I pulled down included a number of
changes I don't know which one fixed this.