MySQL Bugs: #26324: falcon crashes while updating a blob record

Bug #26324	falcon crashes while updating a blob record
Submitted:	13 Feb 2007 15:22	Modified:	3 May 2007 10:52
Reporter:	Shane Bester (Platinum Quality Contributor)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Falcon storage engine	Severity:	S1 (Critical)
Version:	5.2.3-falcon-alpha-debug	OS:	Linux (suse9.3 x86)
Assigned to:	Jim Starkey	CPU Architecture:	Any
Tags:	crash, UPDATE

Description:
During some simple tests, falcon crashes after many SQL statements:

start transaction..
insert into ... (record with blob)..
select c1 from ...
update table ...
update table ... (change blob)
rollback
delete from ... order by .. limit 10

Version: '5.2.3-falcon-alpha-debug'  socket: '/tmp/mysql.sock'  port: 3306  yes
database open failed: can't open file "/home/sbester/server/5.2/mysql-5.2.3-falcon-alpha-linux-i686/data/test.fts": No such file or directory (2)
mysqld got signal 11;
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=8388572
read_buffer_size=131072
max_used_connections=17
max_connections=151
threads_connected=17
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 336762 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x8f64bc8
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...
Cannot determine thread, fp=0x4b8fbf0c, backtrace may not be correct.
Stack range sanity check OK, backtrace follows:
0x81f5637 handle_segfault + 417
0x8381c7c _ZN5Table13duplicateBlobEP5ValueiP6Record + 252
0x8381ed9 _ZN5Table14garbageCollectEP6RecordS1_P11Transactionb + 323
0x837ff53 _ZN5Table14rollbackRecordEP13RecordVersion + 161
0x83d0641 _ZN13RecordVersion8rollbackEv + 35
0x83875fa _ZN11Transaction17rollbackSavepointEi + 212
0x83770a0 _ZN15StorageDatabase17savepointRollbackEP10Connectioni + 32
0x83760e6 _ZN17StorageConnection17savepointRollbackEi + 34
0x8376305 _ZN17StorageConnection12rollbackVerbEv + 31
0x8378dec _ZN14StorageHandler12rollbackVerbEP3THD + 124
0x8371f6d _ZN15NfsStorageTable8rollbackEP10handlertonP3THDb + 133
0x82d50a2 _Z17ha_rollback_transP3THDb + 276
0x82d5226 _Z25ha_autocommit_or_rollbackP3THDi + 126
0x827f7b3 _Z12mysql_updateP3THDP13st_table_listR4ListI4ItemES6_PS4_jP8st_ordery15enum_duplicatesb + 6009
0x82118d9 _Z21mysql_execute_commandP3THD + 9379
0x8218a91 _Z11mysql_parseP3THDPcj + 353
0x820df51 _Z16dispatch_command19enum_server_commandP3THDPcj + 2077
0x820d729 _Z10do_commandP3THD + 603
0x820c816 handle_one_connection + 900
0x40250aa7 _end + 933750423
0x401e6c2e _end + 933316638
New value of fp=(nil) failed sanity check, terminating stack trace!
Please read http://dev.mysql.com/doc/mysql/en/using-stack-trace.html and follow instructions on how to resolve the stack trace. Resolved
stack trace is much more helpful in diagnosing the problem, so please do 
resolve it
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0x909e0f0 = update t1 set c3=md5(c3)
thd->thread_id=136
The manual page at http://www.mysql.com/doc/en/Crashing.html contains
information that should help you find out what is causing the crash.

Number of processes running now: 0
070213 15:10:46  mysqld restarted

How to repeat:
will create standalone testcase soon.
ran my tester with parameters --host=192.168.250.2:3306 --database=test --user=root --queryfile=falcon.query --threads=15 --duration=5600 --shuffle-queries=1 --generate-testcase=0

Suggested fix:
don't crash

some further information about the test run.

Attachment: bug26324_info.txt (text/plain), 206.00 KiB.

see header of file for compile instructions + host,user,database,port

Attachment: testcase.c (text/plain), 7.03 KiB.

attached is the testcase.c that caused the reported stack trace.  However, the last 3 times I've run it for 10 - 25 minutes each, it crashed with a different stack trace (reported in separate bugs).  So, the developers should determine if there's a common cause or not.

More predictable version of the test case

Attachment: falcon_bug_26324.c (text/x-csrc), 8.68 KiB.

Seed value and number of threads is settable via command line option now.

Attachment: falcon_bug_26324.tar.gz (application/x-gzip, text), 3.50 KiB.

./falcon_bug_26324  -r900 -s707

Crashes with:
Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 1158465888 (LWP 3328)]
0x000000000086da8d in Transaction::getRelativeState (this=0x2aaaab0a2368, record=0x0) at Transaction.cpp:884
884             return getRelativeState(record->getTransaction(), record->getTransactionId());
(gdb) bt
#0  0x000000000086da8d in Transaction::getRelativeState (this=0x2aaaab0a2368, record=0x0)
    at Transaction.cpp:884
#1  0x0000000000864c2f in Table::fetchForUpdate (this=0x2aaaab087a68, transaction=0x2aaaab0a2368,
    source=0x2aaaab0c7748) at Table.cpp:2822
#2  0x0000000000853914 in StorageDatabase::nextRow (this=0x2aaaab049fa8, storageTable=0x2aaaadc0dd88,
    recordNumber=345, lockForUpdate=true) at StorageDatabase.cpp:264
#3  0x0000000000858a73 in StorageTable::next (this=0x2aaaadc0dd88, recordNumber=345, lockForUpdate=true)
    at StorageTable.cpp:122
#4  0x000000000084d452 in NfsStorageTable::rnd_next (this=0x104c558, buf=0x104c788 "�Z�r ")
    at ha_falcon.cpp:466
#5  0x0000000000778ea9 in rr_sequential (info=0x450ca7b0) at records.cc:363
#6  0x0000000000712bf6 in mysql_update (thd=0x104a188, table_list=0x105c398, fields=@0x104bc18,
    values=@0x104bfc8, conds=0x0, order_num=0, order=0x0, limit=18446744073709551591,
    handle_duplicates=DUP_ERROR, ignore=false) at sql_update.cc:466
#7  0x000000000067895f in mysql_execute_command (thd=0x104a188) at sql_parse.cc:2536
#8  0x000000000067ec86 in mysql_parse (thd=0x104a188, inBuf=0x105c2e8 "UPDATE t1 SET c2 = md5(c2)",
    length=26) at sql_parse.cc:5274
#9  0x000000000067f94c in dispatch_command (command=COM_QUERY, thd=0x104a188,
    packet=0x10855a9 "UPDATE t1 SET c2 = md5(c2)", packet_length=27) at sql_parse.cc:896
#10 0x0000000000680cfa in do_command (thd=0x104a188) at sql_parse.cc:662
#11 0x000000000066ed2c in handle_one_connection (arg=0x104a188) at sql_connect.cc:1089
#12 0x00002b8e75816f1a in start_thread () from /lib/libpthread.so.0
#13 0x00002b8e75ecb602 in clone () from /lib/libc.so.6
#14 0x0000000000000000 in ?? ()

Latest version

Attachment: falcon_bug_26324.tar.gz (application/x-gzip, text), 3.64 KiB.

Hitting another assertion now:

hakan@lu0011:~/work/workspace/MySQL_Test_Cases$ ./falcon_bug_26324 -r900 -s707
Running initializations ...
Pre-generating 16777216 bytes of random data.
About to spawn 2 threads
1 2
Completed spawning new database worker threads.
Runtime is 900.
Seed value is 707.
Isolation level is READ-COMMITTED.
Testcase is now running, so watch for error output.

(gdb) f 4
#4  0x00000000008de191 in RecordVersion::getEncodedRecord (this=0x2aaaab0e25a0) at RecordVersion.cpp:311
311             ASSERT(encoding == shortVector);
(gdb) p encoding
$1 = 0 '\0'
(gdb) p shortVector
No symbol "shortVector" in current context.
(gdb)      

Program received signal SIGILL, Illegal instruction.
[Switching to Thread 1082665312 (LWP 20107)]
0x00002b6f0b7a32ac in raise () from /lib/libpthread.so.0
(gdb) bt
#0  0x00002b6f0b7a32ac in raise () from /lib/libpthread.so.0
#1  0x00000000008a323c in Error::debugBreak () at Error.cpp:92
#2  0x00000000008a3355 in Error::error (string=0xc1c368 "assertion failed at line %d in file %s\n")
    at Error.cpp:69
#3  0x00000000008a33eb in Error::assertionFailed (fileName=0xc21a60 "RecordVersion.cpp", line=311)
    at Error.cpp:76
#4  0x00000000008de191 in RecordVersion::getEncodedRecord (this=0x2aaaab0e25a0) at RecordVersion.cpp:311
#5  0x0000000000858860 in StorageTable::setRecord (this=0x2aaaaafa7b98, newRecord=0x2aaaab0e25a0, locked=true)
    at StorageTable.cpp:305
#6  0x0000000000853d08 in StorageDatabase::nextRow (this=0x2aaaab04a0c0, storageTable=0x2aaaaafa7b98,
    recordNumber=542, lockForUpdate=true) at StorageDatabase.cpp:291
#7  0x0000000000858dd7 in StorageTable::next (this=0x2aaaaafa7b98, recordNumber=541, lockForUpdate=true)
    at StorageTable.cpp:121
#8  0x000000000084d5a4 in NfsStorageTable::rnd_next (this=0x103b778, buf=0x103b9b0 "�\202?� ")
    at ha_falcon.cpp:469
#9  0x0000000000778f19 in rr_sequential (info=0x408807b0) at records.cc:363
#10 0x0000000000712c66 in mysql_update (thd=0x10200a8, table_list=0x104f2a8, fields=@0x1021b38,
    values=@0x1021ee8, conds=0x0, order_num=0, order=0x0, limit=18446744073709551614,
    handle_duplicates=DUP_ERROR, ignore=false) at sql_update.cc:466

Latest version

Attachment: falcon_bug_26324.tar.gz (application/x-gzip, text), 3.66 KiB.

Seems to be fixed!

hakan@lu0011:~/work/workspace/MySQL_Test_Cases$ ./falcon_bug_26324 -r500 -s707
Running initializations ...
Pre-generating 16777216 bytes of random data.
About to spawn 2 threads
1 2
Completed spawning new database worker threads.
Runtime is 500.
Seed value is 707.
Isolation level is READ-COMMITTED.
Testcase is now running, so watch for error output.
Waiting for worker threads to finish ...
hakan@lu0011:~/work/workspace/MySQL_Test_Cases$

New failure with seed value of 4

./falcon_bug_26324 -r600 -s4
Running initializations ...
Pre-generating 16777216 bytes of random data.
About to spawn 2 threads
1 2
Completed spawning new database worker threads.
Runtime is 600.
Seed value is 4.
Isolation level is READ-COMMITTED.
Testcase is now running, so watch for error output.

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 1076373856 (LWP 28502)]
0x0000000000905270 in Cache::findBuffer (this=0x2a9e459d48,
dbb=0x2a9e497cf0, pageNumber=1187, lockType=Exclusive,
    sync=0x4027ff90) at Cache.cpp:334
334                                     for (candidate = bdb;
candidate->higher; candidate = candidate->higher->higher)
(gdb) p  candidate
$1 = (Bdb *) 0x2a9e3e47c8
(gdb) p bdb
$2 = (Bdb *) 0x2a9e3e47c8
(gdb) p candidate->higher
$3 = (class PagePrecedence *) 0x0
(gdb)

Full backtrace
(gdb) bt
#0  0x0000000000905270 in Cache::findBuffer (this=0x2a9e459d48,
dbb=0x2a9e497cf0, pageNumber=1187,
    lockType=Exclusive, sync=0x4027ff90) at Cache.cpp:334
#1  0x0000000000904f7f in Cache::fakePage (this=0x2a9e459d48,
dbb=0x2a9e497cf0, pageNumber=1187,
    type=PAGE_data_overflow, transId=30149) at Cache.cpp:259
#2  0x0000000000872b13 in Dbb::fakePage (this=0x2a9e497cf0,
pageNumber=1187, pageType=PAGE_data_overflow,
    transId=30149) at Dbb.cpp:193
#3  0x00000000008ace8c in PageInventoryPage::allocPage
(dbb=0x2a9e497cf0, pageType=PAGE_data_overflow,
    transId=30149) at PageInventoryPage.cpp:98
#4  0x0000000000872c25 in Dbb::allocPage (this=0x2a9e497cf0,
pageType=PAGE_data_overflow, transId=30149)
    at Dbb.cpp:226
#5  0x00000000008c8546 in Section::storeTail (this=0x2a9e4d4478,
stream=0x40280400, maxRecord=4084,
    pLength=0x402801f8, transId=30149, earlyWrite=true) at
Section.cpp:658
#6  0x00000000008c8189 in Section::storeRecord (this=0x2a9e4d4478,
recordLocatorPage=0x2aa057f000,
    indexPageNumber=104, index=0x2aa057ffc0, stream=0x40280400,
transId=30149, earlyWrite=true) at Section.cpp:572
#7  0x00000000008c7eaf in Section::updateRecord (this=0x2a9e4d4478,
recordNumber=502, stream=0x40280400,
    transId=30149, earlyWrite=true) at Section.cpp:511
#8  0x0000000000872f76 in Dbb::updateRecord (this=0x2a9e497cf0,
sectionId=44, recordId=502, stream=0x40280400,
    transId=30149, earlyWrite=true) at Dbb.cpp:310
#9  0x0000000000872f29 in Dbb::updateBlob (this=0x2a9e497cf0,
sectionId=44, recordId=502, stream=0x40280400,
    transId=30149) at Dbb.cpp:304

The originally discovered crash was fixed. However, extending and tweaking the test case is revealing other bugs which will be covered in separate bug reports.

Best regards,

Hakan

A note has been added to the 6.0.0 changelog.