Bug #38566 Falcon crash in RecordVersion::thaw at RecordVersion.cpp:421
Submitted: 5 Aug 2008 11:21 Modified: 8 Jan 2009 17:19
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)

[5 Aug 2008 11:21] Philip Stoev
Description:
When executing an insert/update workload with falcon_index_chill_threshold=4K  and falcon_record_chill_threshold=4K, Falcon crashed as follows:

#0  0x00110416 in __kernel_vsyscall ()
#1  0x00581c78 in pthread_kill () from /lib/libpthread.so.0
#2  0x087bdb43 in my_write_core (sig=11) at stacktrace.c:307
#3  0x082acd2b in handle_segfault (sig=11) at mysqld.cc:2657
#4  <signal handler called>
#5  0x085b54dc in RecordVersion::thaw (this=0xaf23e7d8) at RecordVersion.cpp:421
#6  0x085302b9 in Table::fetchForUpdate (this=0xb7406e68, transaction=0xb7206518, source=0xaf23e7d8, usingIndex=false) at Table.cpp:3513
#7  0x0851bd42 in StorageDatabase::nextRow (this=0xb707d130, storageTable=0xb7474c20, recordNumber=1002, lockForUpdate=true) at StorageDatabase.cpp:286
#8  0x08521eae in StorageTable::next (this=0xb7474c20, recordNumber=1000, lockForUpdate=true) at StorageTable.cpp:169
#9  0x0851572a in StorageInterface::rnd_next (this=0xa2575e8, buf=0xa2577b0 "") at ha_falcon.cpp:586
#10 0x083c8808 in rr_sequential (info=0xa706b33c) at records.cc:366
#11 0x0835fc35 in mysql_update (thd=0x9f43668, table_list=0xa276118, fields=@0x9f44b00, values=@0x9f44d30, conds=0xa2767c0, order_num=0, order=0x0,
    limit=18446744073709550615, handle_duplicates=DUP_ERROR, ignore=false) at sql_update.cc:573
#12 0x082bf817 in mysql_execute_command (thd=0x9f43668) at sql_parse.cc:2846
#13 0x082c63e1 in mysql_parse (thd=0x9f43668, inBuf=0xa275df0 "UPDATE E AS X SET `int_key` = 206 WHERE X . `int_nokey` > 176", length=61,
    found_semicolon=0xa706c270) at sql_parse.cc:5809
#14 0x082c6e55 in dispatch_command (command=COM_QUERY, thd=0x9f43668, packet=0xa22b751 "UPDATE E AS X SET `int_key` = 206 WHERE X . `int_nokey` > 176",
    packet_length=61) at sql_parse.cc:1050
#15 0x082c8145 in do_command (thd=0x9f43668) at sql_parse.cc:723
#16 0x082b5e23 in handle_one_connection (arg=0x9f43668) at sql_connect.cc:1153
#17 0x0057d32f in start_thread () from /lib/libpthread.so.0
#18 0x0049a27e in clone () from /lib/libc.so.6

The crash is here:

416                             }
417                     }
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); <<<<<<<<<<<<<< HERE
422
423             ASSERT(bytesRestored > 0 || data.record == NULL);
424             state = recData;
425

(gdb) print trans
$2 = (class Transaction *) 0x0

How to repeat:
If this is repeatable, a test case will be uploaded shortly.

Suggested fix:
If a non-null trans is important for the functioning of this code, there should have been a separate assertion checking for it, so that the crash is not when the error message is being printed.
[5 Aug 2008 11:55] Philip Stoev
To reproduce this bug, please clone the mysql-test-extra-6.0 repository and execute

$ cd mysql-test-extra-6.0/mysqltest/gentest
$ perl runall.pl \
  --basedir=/path/to/6.0-falcon/ \
  --engine=falcon \
  --grammar=conf/chill_thaw.yy \
  --threads=20 --queries=100000 \
  --mysqld=--falcon_debug_mask=7167 \
  --mysqld=--falcon_index_chill_threshold=4K \
  --mysqld=--falcon_record_chill_threshold=4K

The crash should happen within less than a mintute, after a few dozen chill/thaw operations.

During the Falcon Boston meeting, it was agreed that 4K is an acceptable value for those parameters, that is why I am testing with it. Values at least up to 32K will also produce crashes. The required grammar file is part of the mysql-test-extra-6.0 repository and does not have to be obtained separately. If the chill options are set to their default values, no crash occurs.
[10 Aug 2008 13:00] Philip Stoev
This bug is also observed with --threads=1, that is, in a non-concurrent environment.
[19 Aug 2008 21:01] Kevin Lewis
Related to falcon_record_chill_threshold=4K
[27 Aug 2008 7:11] 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/52651

2801 Christopher Powers	2008-08-27
      Bug #38566 Falcon crash in RecordVersion::thaw at RecordVersion.cpp:421
      
      Removed unnecessary log messages
      Modified assertions to accommodate race condition where two threads thaw the same record
[8 Jan 2009 17:19] MC Brown
A noter has been added to the 6.0.8 changelog: 

Executing a light INSERT and UPDATE workload with falcon_index_chill_threshold set to 4K and falcon_record_chill_threshold set to to 4K, MySQL could crash