MySQL Bugs: #36294: Assertion in Cache::writePage

Bug #36294	Assertion in Cache::writePage
Submitted:	23 Apr 2008 15:32	Modified:	5 Oct 2008 15:19
Reporter:	Vladislav Vaintroub	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Falcon storage engine	Severity:	S3 (Non-critical)
Version:	mysql-6.0-falcon-team,6.0.5	OS:	Any
Assigned to:	Vladislav Vaintroub	CPU Architecture:	Any

Description:
while trying to reproduce Bug#29648, hit assertion

Assert happends during insert/select of 2 Mio rows
The assertion:
	ASSERT(!(bdb->flags & BDB_write_pending));

bdb->flags is 17 (==BDB_dirty|BDB_write_pending)

The callstack:
0000000077244EA0    ntdll.dll!DbgBreakPoint()
00000001407D9850    mysqld.exe!Error::debugBreak()[error.cpp:94]
00000001407D972B    mysqld.exe!Error::error()[error.cpp:71]
00000001407D980C    mysqld.exe!Error::assertionFailed()[error.cpp:77]
0000000140874793    mysqld.exe!Cache::writePage()[cache.cpp:514]
0000000140874184    mysqld.exe!Cache::findBuffer()[cache.cpp:416]
000000014087375D    mysqld.exe!Cache::fetchPage()[cache.cpp:249]
0000000140850692    mysqld.exe!Dbb::fetchPage()[dbb.cpp:220]
00000001408508CA    mysqld.exe!Dbb::handoffPage()[dbb.cpp:268]
000000014085B71D    mysqld.exe!Section::fetchRecord()[section.cpp:816]
00000001408511B8    mysqld.exe!Dbb::fetchRecord()[dbb.cpp:394]
00000001407EC147    mysqld.exe!Table::databaseFetch()[table.cpp:611]
00000001407EBAB7    mysqld.exe!Table::fetchNext()[table.cpp:498]
00000001407CC44A    mysqld.exe!StorageDatabase::nextRow()[storagedatabase.cpp:242]
00000001407BB6F6    mysqld.exe!StorageTable::next()[storagetable.cpp:161]
00000001407AA2E6    mysqld.exe!StorageInterface::rnd_next()[ha_falcon.cpp:568]
0000000140226EF7    mysqld.exe!rr_sequential()[records.cc:366]
00000001403A3505    mysqld.exe!sub_select()[sql_select.cc:13346]
00000001403A2F78    mysqld.exe!do_select()[sql_select.cc:13087]
00000001403810CD    mysqld.exe!JOIN::exec()[sql_select.cc:2340]
000000014038382A    mysqld.exe!mysql_select()[sql_select.cc:2929]
0000000140379A9E    mysqld.exe!handle_select()[sql_select.cc:289]
000000014032D198    mysqld.exe!mysql_execute_command()[sql_parse.cc:2982]
000000014033694D    mysqld.exe!mysql_parse()[sql_parse.cc:5756]
0000000140328351    mysqld.exe!dispatch_command()[sql_parse.cc:1047]
00000001403278B7    mysqld.exe!do_command()[sql_parse.cc:722]
0000000140493D86    mysqld.exe!handle_one_connection()[sql_connect.cc:1134]
00000001405A4F15    mysqld.exe!pthread_start()[my_winthread.c:86]
0000000140911165    mysqld.exe!_callthreadstart()[thread.c:295]
0000000140911137    mysqld.exe!_threadstart()[thread.c:277]

How to repeat:
Here are the statements that lead to error 

set falcon_record_memory_max=500*1024*1024;
create tablespace gimdata add datafile 'gimdata.fts' engine=falcon;
create table ftest (id serial, col1 varchar(500)) engine=falcon tablespace gimdata;
insert into ftest values (null,repeat("a",500));
insert into ftest(col1) select col1 from ftest;
insert into ftest(col1) select col1 from ftest;
insert into ftest(col1) select col1 from ftest;
insert into ftest(col1) select col1 from ftest;
insert into ftest(col1) select col1 from ftest;
insert into ftest(col1) select col1 from ftest;
insert into ftest(col1) select col1 from ftest;
insert into ftest(col1) select col1 from ftest;
insert into ftest(col1) select col1 from ftest;
insert into ftest(col1) select col1 from ftest;
insert into ftest(col1) select col1 from ftest;
insert into ftest(col1) select col1 from ftest;
insert into ftest(col1) select col1 from ftest;
insert into ftest(col1) select col1 from ftest;
insert into ftest(col1) select col1 from ftest;
insert into ftest(col1) select col1 from ftest;
insert into ftest(col1) select col1 from ftest;
insert into ftest(col1) select col1 from ftest;
insert into ftest(col1) select col1 from ftest;
insert into ftest(col1) select col1 from ftest;
insert into ftest(col1) select col1 from ftest;
insert into ftest(col1) select col1 from ftest;

create table t2 (c1 int) engine=falcon tablespace gimdata;
insert into t2 values(1);

Thank you for the bug report.

A new stacktrace from todays run

0000000077B34EA0    ntdll.dll!DbgBreakPoint()
00000001407DA980    mysqld.exe!Error::debugBreak()[error.cpp:94]
00000001407DA85B    mysqld.exe!Error::error()[error.cpp:71]
00000001407DA93C    mysqld.exe!Error::assertionFailed()[error.cpp:77]
000000014089CFA2    mysqld.exe!SerialLogControl::nextRecord()[seriallogcontrol.cpp:316]
00000001408D894B    mysqld.exe!SerialLogTransaction::commit()[seriallogtransaction.cpp:87]
00000001408D8DCA    mysqld.exe!SerialLogTransaction::doAction()[seriallogtransaction.cpp:158]
00000001408D6793    mysqld.exe!Gopher::gopherThread()[gopher.cpp:71]
00000001408D656D    mysqld.exe!Gopher::gopherThread()[gopher.cpp:38]
00000001408062DB    mysqld.exe!Thread::thread()[thread.cpp:163]
0000000140806227    mysqld.exe!Thread::thread()[thread.cpp:141]
00000000779E495D    kernel32.dll!BaseThreadInitThunk()
0000000077B18791    ntdll.dll!RtlUserThreadStart()

The assertion at seriallogcontrol.cpp:316 is

ASSERT(*input >= (LOW_BYTE_FLAG | srlEnd) && *input < (LOW_BYTE_FLAG | srlMax));

input points to the "aaaaaaaa.." string 

As all string values in the test case are repeat('a',500() that means, 

input is the in middle of the record.

Running under debugger showed yet another crash.

now this is in Cache::fetchPage/IO::readPage/IO::longSeek, due to fileId == -1

in the error log, there is a C runtime warning
lseeki64.c(90) : Assertion failed: ("Invalid file descriptor. File possibly closed by a different thread",0)
The file is the tablespace  gimdata.fts.

the debugger output indicates there were C++ exception previously , so the file file probably was closed in one of the catch blocks.

Here the callstack:

 	mysqld.exe!Error::error(const char * string=0x0000000140dd03b0, ...)  Line 71	C++
>	mysqld.exe!IO::longSeek(__int64 offset=5066752)  Line 364	C++
 	mysqld.exe!IO::pread(__int64 offset=5066752, int length=4096, unsigned char * buffer=0x0000000004dff000)  Line 508	C++
 	mysqld.exe!IO::readPage(Bdb * bdb=0x000000000478d338)  Line 238 + 0x24 bytes	C++
 	mysqld.exe!Cache::fetchPage(Dbb * dbb=0x0000000004978aa0, int pageNumber=1237, PageType pageType=PAGE_any, LockType lockType=Exclusive)  Line 261	C++
 	mysqld.exe!Dbb::fetchPage(int pageNumber=1237, PageType pageType=PAGE_any, LockType lockType=Exclusive)  Line 220	C++
 	mysqld.exe!IndexRootPage::deleteIndex(Dbb * dbb=0x0000000004978aa0, int indexId=0, unsigned int transId=98)  Line 700 + 0x1d bytes	C++
 	mysqld.exe!SRLDeleteIndex::commit()  Line 123	C++
 	mysqld.exe!SerialLogTransaction::commit()  Line 93	C++
 	mysqld.exe!SerialLogTransaction::doAction()  Line 158	C++
 	mysqld.exe!Gopher::gopherThread()  Line 71	C++
 	mysqld.exe!Gopher::gopherThread(void * arg=0x0000000004932358)  Line 38	C++
 	mysqld.exe!Thread::thread()  Line 163	C++
 	mysqld.exe!Thread::thread(void * parameter=0x000000000493e180)  Line 141	C++
 	kernel32.dll!BaseThreadInitThunk()  + 0xd bytes	
 	ntdll.dll!RtlUserThreadStart()  + 0x21 bytes

The initial assertion from this bug also happens when running the large_tests.alter_table test under Falcon on Windows, which is similar in nature to the test Vlad is using. I used 8GB of falcon_record_memory_max:

$ perl mysql-test-run.pl --big-test --master_port=123456 --suite=large_tests --testcase-timeout=10000 --suite-timeout=10000 --mysqld=--falcon_record_memory_max=8GB

Backtrace is :

>	ntdll.dll!0000000077ef2aa0() 	
 	[Frames below may be incorrect and/or missing, no symbols loaded for ntdll.dll]	
 	mysqld.exe!Error::error(const char * string=0x0000000000b35cf0, ...)  Line 71	C++
 	mysqld.exe!Error::assertionFailed(const char * fileName=0x0000000000000000, int line=0)  Line 76 + 0xf bytes	C++
 	mysqld.exe!Cache::writePage(Bdb * bdb=0x0000000001aae2a0, int type=1)  Line 514 + 0x19 bytes	C++
 	mysqld.exe!Cache::findBuffer(Dbb * dbb=0x0000000001c61220, int pageNumber=30020776, LockType lockType=5839)  Line 416	C++
 	mysqld.exe!Cache::fetchPage(Dbb * dbb=0x0000000000000000, int pageNumber=0, PageType pageType=PAGE_any, LockType lockType=Exclusive)  Line 249 + 0x14 bytes	C++
 	mysqld.exe!Dbb::fetchPage(int pageNumber=1050767, PageType pageType=64572192, LockType lockType=32587776)  Line 220	C++
 	mysqld.exe!Dbb::handoffPage(Bdb * bdb=0x0000000001ca14a8, int pageNumber=25423, PageType pageType=33873920, LockType lockType=Exclusive)  Line 270	C++
 	mysqld.exe!IndexRootPage::addIndexEntry(Dbb * dbb=0x0000000000000000, int indexId=2, IndexKey * key=0x00000000ffffffff, int recordNumber=0, unsigned int transId=0)  Line 167 + 0x1d bytes	C++
 	mysqld.exe!IndexRootPage::indexMerge(Dbb * dbb=0x0000000000000000, int indexId=9227757, SRLUpdateIndex * logRecord=0x0000000000000000, unsigned int transId=29762528)  Line 1006	C++
 	mysqld.exe!SRLUpdateIndex::commit()  Line 158	C++
 	mysqld.exe!SerialLogTransaction::commit()  Line 87	C++
 	mysqld.exe!Gopher::gopherThread()  Line 71	C++
 	mysqld.exe!Thread::thread()  Line 163	C++
 	mysqld.exe!Thread::thread(void * parameter=0x0000000077d6b6a0)  Line 141	C++
 	kernel32.dll!0000000077d6b6da() 	
 	kernel32.dll!0000000077d6b6a0()

Jim pushed this change today which should make the flags variable thread safe.
The BDB_write_pending flag that was involved in this assertion is no longer used.
It was not really needed anymore.

ChangeSet@1.2667.1.7, 2008-05-08 16:37:28-04:00, jas@rowvwade. +4 -0
  Replaced Bdb::flags with individual booleans for "dirty" and "registered"
  (by PageWriter) to get around non-thread safe usage.
  This is a fix for bugs 36294 and 36367.

This fix is in version 6.0.6

When running falcon_bug_36294 in ramdisk following assertion is hit sometimes:

./mysql-test-run.pl --force --mem --skip-ndb --suite=falcon_team falcon_bug_36294

=======================================================

TEST                           RESULT         TIME (ms)
-------------------------------------------------------

falcon_team.falcon_bug_36294   [ fail ]

mysqltest: At line 65: query 'DROP TABLE ftest' failed: 2006: MySQL server has gone away

The result from queries just before the failure was:
*** Bug #36294 ***
SET @@storage_engine = 'Falcon';
DROP TABLE IF EXISTS ftest;

/home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(my_print_stacktrace+0x2e)[0xa5e378]
/home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(handle_segfault+0x25c)[0x66eacd]
/lib/libpthread.so.0[0x7fd79a9eba90]
/lib/libpthread.so.0(raise+0x2b)[0x7fd79a9eb94b]
/home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(Error::debugBreak()+0xe)[0x8b2e48]
/home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(Error::error(char const*, ...)+0xea)[0x8b2f38]
/home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(Error::assertionFailed(char const*, char const*, int)+0x19)[0x8b2f9b]
/home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(SerialLogControl::nextRecord()+0x38)[0x8eddb4]
/home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(SerialLogTransaction::commit()+0xc8)[0x8f4a70]
/home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(SerialLogTransaction::doAction()+0x11)[0x8f4af3]
/home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(Gopher::gopherThread()+0x11c)[0x91d296]
/home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(Gopher::gopherThread(void*)+0x9)[0x91d3bb]
/home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(Thread::thread()+0x3f)[0x884739]
/home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(Thread::thread(void*)+0x9)[0x8848bb]
/lib/libpthread.so.0[0x7fd79a9e3fc7]
/lib/libc.so.6(clone+0x6d)[0x7fd79953f7cd]
[Falcon] Error: assertion (*input >= (LOW_BYTE_FLAG | srlEnd) && *input < (LOW_BYTE_FLAG | srlMax)) failed at line 316 in file SerialLogControl.cpp

Hakan, this problem about assertion in Cache::writePage(), not in SerialLog::nextRecord(). The assertion you're seeeing is the synopsis for Bug#36294

small correction to previous entry : the correct bugnr for crash in SerialLogControl::nextRecord() is Bug#36631.

Uups, sorry Vlad. You are right!

Documented bugfix in the 6.0.6 changelog as follows:

        Following a number of INSERT ... SELECT statements on a Falcon table,
        creating a second Falcon table using the same tablespace as the table
        into which the inserts were made, then performing a simple INSERT on the
        new table, caused the server to crash.