Bug #38541 Falcon RecordVersion::thaw assertion ""bytesRestored > 0 || data.record == NULL"
Submitted: 4 Aug 2008 14:59 Modified: 13 Dec 2008 9:05
Reporter: Philip Stoev Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Falcon storage engine Severity:S1 (Critical)
Version:6.0-falcon OS:Any
Assigned to: Christopher Powers CPU Architecture:Any
Tags: F_CHILL THAW
Triage: Triaged: D1 (Critical)

[4 Aug 2008 14:59] Philip Stoev
Description:
When executing a SELECT/UPDATE/INSERT/DELETE workload under falcon_{record|index}_chill_threshold = 1024, Falcon asserted as follows:

#0  0x00110416 in __kernel_vsyscall ()
#1  0x00581c78 in pthread_kill () from /lib/libpthread.so.0
#2  0x087bdb43 in my_write_core (sig=6) at stacktrace.c:307
#3  0x082acd2b in handle_segfault (sig=6) at mysqld.cc:2657
#4  <signal handler called>
#5  0x00110416 in __kernel_vsyscall ()
#6  0x00584fe0 in raise () from /lib/libpthread.so.0
#7  0x0857bfa8 in Error::debugBreak () at Error.cpp:94
#8  0x0857c025 in Error::error (string=0x8965978 "assertion (%s) failed at line %d in file %s\n") at Error.cpp:71
#9  0x0857c0cf in Error::assertionFailed (text=0x896a9e4 "bytesRestored > 0 || data.record == NULL", fileName=0x896a9d1 "RecordVersion.cpp", line=423)
    at Error.cpp:78
#10 0x085b5520 in RecordVersion::thaw (this=0xa6ece8e8) at RecordVersion.cpp:423
#11 0x08536465 in Record::getRecordData (this=0xa6ece8e8) at Record.h:130
#12 0x085b5adf in RecordVersion::fetchVersionRecursive (this=0xa6ece8e8, trans=0xb72f2700) at RecordVersion.cpp:149
#13 0x085b5ba1 in RecordVersion::fetchVersion (this=0xa6ece8e8, trans=0xb72f2700) at RecordVersion.cpp:127
#14 0x08590f19 in IndexWalker::getValidatedRecord (this=0xb4f47f98, recordId=265, lockForUpdate=false) at IndexWalker.cpp:152
#15 0x0860c044 in WalkIndex::getNext (this=0xb4f47f98, lockForUpdate=false) at WalkIndex.cpp:76
#16 0x0851b826 in StorageDatabase::nextIndexed (this=0xb713b130, storageTable=0xb4fa31b0, indexWalker=0xb4f47f98, lockForUpdate=false)
    at StorageDatabase.cpp:483
#17 0x08521e34 in StorageTable::nextIndexed (this=0xb4fa31b0, recordNumber=0, lockForUpdate=false) at StorageTable.cpp:180
#18 0x08514fcc in StorageInterface::index_next (this=0xb7ca170, buf=0xb7ca338 "") at ha_falcon.cpp:1597
#19 0x08513bf9 in StorageInterface::read_range_first (this=0xb7ca170, start_key=0xb7ca204, end_key=0x0, eq_range_arg=false, sorted=true)
    at ha_falcon.cpp:1565
#20 0x083ce5fa in handler::multi_range_read_next (this=0xb7ca170, range_info=0xa7fb2cb0) at handler.cc:4258
#21 0x083aeeef in QUICK_RANGE_SELECT::get_next (this=0xb907cc0) at opt_range.cc:8518
#22 0x083c8897 in rr_quick (info=0xae7067c) at records.cc:298
#23 0x0832001f in join_init_read_record (tab=0xae70638) at sql_select.cc:14481
#24 0x08323c61 in sub_select (join=0xae6f248, join_tab=0xae70638, end_of_records=false) at sql_select.cc:13636
#25 0x08330947 in do_select (join=0xae6f248, fields=0xb047c60, table=0x0, procedure=0x0) at sql_select.cc:13387
#26 0x0834302a in JOIN::exec (this=0xae6f248) at sql_select.cc:2811
#27 0x0833e4e3 in mysql_select (thd=0xb0467c8, rref_pointer_array=0xb047cd0, tables=0xaf3a4e0, wild_num=0, fields=@0xb047c60, conds=0xaf3b368, og_num=1,
    order=0xaf3b500, group=0x0, having=0x0, proc_param=0x0, select_options=2149337600, result=0xaf3b598, unit=0xb047934, select_lex=0xb047bcc)
    at sql_select.cc:3001
#28 0x0834333a in handle_select (thd=0xb0467c8, lex=0xb0478d8, result=0xaf3b598, setup_tables_done_option=0) at sql_select.cc:302
#29 0x082bbbc8 in execute_sqlcom_select (thd=0xb0467c8, all_tables=0xaf3a4e0) at sql_parse.cc:4845
#30 0x082bd3e8 in mysql_execute_command (thd=0xb0467c8) at sql_parse.cc:2022
#31 0x082c63e1 in mysql_parse (thd=0xb0467c8,
    inBuf=0xaf3a078 "SELECT X . int_key FROM E AS X LEFT JOIN A AS Y ON ( X . int_key = Y . int_key ) WHERE X . int_key > 99 ORDER BY X . int_key LIMIT 118", length=134, found_semicolon=0xa7fb4270) at sql_parse.cc:5809
#32 0x082c6e55 in dispatch_command (command=COM_QUERY, thd=0xb0467c8, packet=0xb048af9 "", packet_length=134) at sql_parse.cc:1050
#33 0x082c8145 in do_command (thd=0xb0467c8) at sql_parse.cc:723
#34 0x082b5e23 in handle_one_connection (arg=0xb0467c8) at sql_connect.cc:1153
#35 0x0057d32f in start_thread () from /lib/libpthread.so.0
#36 0x0049a27e in clone () from /lib/libc.so.6

The assertion is here:

418
419             if (bytesRestored <= 0)
420                     Log::debug("RecordVersion::thaw: writePending %d, was %d, recordFetched %d, data %p\n",
421                                             trans->writePending, wasWritePending, recordFetched, data.record);
422
423             ASSERT(bytesRestored > 0 || data.record == NULL);  <<<<<< HERE
424             state = recData;
425
426             return bytesRestored;
427     }

(gdb) print data.record
$3 = 0xa6edda30 "\030"

How to repeat:
If this is repeatable, a test case will follow.
[28 Aug 2008 13:30] Kevin Lewis
Chris,  This looks like the concurrent thaw issue you just fixed for Bug#38566.
[9 Sep 2008 18:28] Ann Harrison
The value of falcon_{record|index}_chill_threshold defaults to 5MB, and
the documentation will strongly recommend against lowering it.  We've
made lower levels available for stress testing in-house.
[24 Oct 2008 5:09] 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/56961

2880 Christopher Powers	2008-10-24
      Bug#36631,"Assertion in SerialLogControl::nextRecord"
      Bug#38541,"Falcon RecordVersion::thaw assertion """"bytesRestored > 0 || data.record == NULL"""
      Bug#38567,"Falcon crash in  Record::getEncodedRecord at Record.cpp:743"
      Bug#38569,"Falcon assertion in SRLUpdateIndex::thaw : type == srlUpdateIndex"
      Bug#39694,"Crash in StorageTable::setRecord during falcon_chill_thaw test"
      Bug#39695,"Crash in SRLUpdateRecords::thaw during falcon_chill_thaw test"
      Bug#39696,"Assertion in Table.cpp (dup->state == recDeleted) fails during falcon_chill_thaw"
      
      Fix 1 of 3 for chill/thaw bugs.
      
      Modified Record::hasRecord() to thaw if necessary, removed redundant record thaws, added exception handling
[24 Oct 2008 5: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/56962

2881 Christopher Powers	2008-10-24
      Bug#36631,"Assertion in SerialLogControl::nextRecord"
      Bug#38541,"Falcon RecordVersion::thaw assertion """"bytesRestored > 0 || data.record == NULL"""
      Bug#38567,"Falcon crash in  Record::getEncodedRecord at Record.cpp:743"
      Bug#38569,"Falcon assertion in SRLUpdateIndex::thaw : type == srlUpdateIndex"
      Bug#39694,"Crash in StorageTable::setRecord during falcon_chill_thaw test"
      Bug#39695,"Crash in SRLUpdateRecords::thaw during falcon_chill_thaw test"
      Bug#39696,"Assertion in Table.cpp (dup->state == recDeleted) fails during falcon_chill_thaw"
      
      Fix 2 of 3 for chill/thaw bugs.
      
      Synchronized record thaw operations using a pool of sync objects in the associated table.
      Record chill operations do not need to be synchronized because chills are performed in one place, and only by the active Transaction.
[26 Oct 2008 15:53] Kevin Lewis
Two patches approved to problems with concurent thaws.
1) enhance hasRecord to thaw when needed.
2) serialize thaws with a hash table of SyncOjects.
[28 Oct 2008 8:10] Bugs System
Pushed into 6.0.8-alpha  (revid:cpowers@mysql.com-20081024053538-6y1ma8lydl93oxza) (version source revid:alik@mysql.com-20081028074021-o49ijs3x4pxj1gbm) (pib:5)
[13 Dec 2008 9:05] MC Brown
No documentation needed (internal change only)