Bug #27951 Falcon crashes with insert into..select from
Submitted: 19 Apr 2007 13:06 Modified: 26 Apr 2007 11:01
Reporter: Miguel Solorzano Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Falcon storage engine Severity:S1 (Critical)
Version:6.0.0-alpha-debug OS:Linux (Fedora Core 6.0 32-bits)
Assigned to: Christopher Powers CPU Architecture:Any
Tags: crash

[19 Apr 2007 13:06] Miguel Solorzano
Description:
Populating a table with insert into..select from... A fresh install of
Falcon crashes:

[miguel@light 5.1f]$ bin/mysql -uroot test
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 6.0.0-alpha-debug Source distribution

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> create table tbfalcon (id serial, col1 varchar(500)) engine=falcon;
Query OK, 0 rows affected (0.38 sec)

mysql> insert into tbfalcon (col1) values (repeat('a',500));
Query OK, 1 row affected (0.01 sec)

mysql> insert into tbfalcon (col1)  select col1 from tbfalcon;
Query OK, 1 row affected (0.02 sec)

<cut>

mysql> insert into tbfalcon (col1)  select col1 from tbfalcon;
Query OK, 8192 rows affected (0.44 sec)
Records: 8192  Duplicates: 0  Warnings: 0

mysql> insert into tbfalcon (col1)  select col1 from tbfalcon;
Query OK, 16384 rows affected (1.44 sec)
Records: 16384  Duplicates: 0  Warnings: 0

mysql> insert into tbfalcon (col1)  select col1 from tbfalcon;
ERROR 2013 (HY000): Lost connection to MySQL server during query

How to repeat:
see description

Suggested fix:
-
[19 Apr 2007 16:41] Hakan Küçükyılmaz
Added test case falcon_bug_27951.test and pushed into 5.1-falcon tree.

Regards, Hakan
[19 Apr 2007 16:46] Hakan Küçükyılmaz
(gdb) f 0
#0  0x000000000086e169 in Transaction::thaw (this=0x0, record=0x2aaaaed6ba18)
    at Transaction.cpp:402
402             SerialLogControl control(database->dbb->serialLog);
(gdb) p database
Cannot access memory at address 0x0
(gdb)

Backtrace is:

Program received signal SIGSEGV, Segmentation fault.
0x000000000086e169 in Transaction::thaw (this=0x0, record=0x2aaaaed6ba18)
    at Transaction.cpp:402
402             SerialLogControl control(database->dbb->serialLog);
(gdb) bt
#0  0x000000000086e169 in Transaction::thaw (this=0x0, record=0x2aaaaed6ba18)
    at Transaction.cpp:402
#1  0x00000000008dd8f4 in RecordVersion::thaw (this=0x2aaaaed6ba18)
    at RecordVersion.cpp:261
#2  0x00000000008dddc8 in RecordVersion::fetchVersion (this=0x2aaaaed6ba18, 
    trans=0x2aaaaad1c758) at RecordVersion.cpp:106
#3  0x0000000000853932 in StorageDatabase::nextRow (this=0x2aaaaacf8058, 
    storageTable=0x2aaaaac55b98, recordNumber=23363, lockForUpdate=false)
    at StorageDatabase.cpp:266
#4  0x0000000000858a73 in StorageTable::next (this=0x2aaaaac55b98, 
    recordNumber=23363, lockForUpdate=false) at StorageTable.cpp:122
#5  0x000000000084d452 in NfsStorageTable::rnd_next (this=0x193b098, 
    buf=0x193b498 "�") at ha_falcon.cpp:466
#6  0x0000000000778ea9 in rr_sequential (info=0x193d500) at records.cc:363
#7  0x00000000006d8abe in sub_select (join=0x2aaaad900988, join_tab=0x193d480, 
    end_of_records=false) at sql_select.cc:10698
#8  0x00000000006e1513 in do_select (join=0x2aaaad900988, fields=0x0, 
    table=0x2aaaad902988, procedure=0x0) at sql_select.cc:10456
#9  0x00000000006f7a49 in JOIN::exec (this=0x2aaaad900988)
    at sql_select.cc:1631
#10 0x00000000006f4ae0 in mysql_select (thd=0x18e1d68, 
    rref_pointer_array=0x18e38d8, tables=0x193cc28, wild_num=0, 
    fields=@0x18e37f8, conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, 
---Type <return> to continue, or q <return> to quit---
    proc_param=0x0, select_options=3489942016, result=0x193cf18, 
    unit=0x18e3330, select_lex=0x18e36f0) at sql_select.cc:2191
#11 0x00000000006f95af in handle_select (thd=0x18e1d68, lex=0x18e3290, 
    result=0x193cf18, setup_tables_done_option=1073741824) at sql_select.cc:257
#12 0x00000000006790c1 in mysql_execute_command (thd=0x18e1d68)
    at sql_parse.cc:2697
#13 0x000000000067ec86 in mysql_parse (thd=0x18e1d68, 
    inBuf=0x193c618 "INSERT INTO t1 (b) SELECT b from t1", length=35)
    at sql_parse.cc:5274
#14 0x000000000067f94c in dispatch_command (command=COM_QUERY, thd=0x18e1d68, 
    packet=0x1934589 "INSERT INTO t1 (b) SELECT b from t1", packet_length=36)
    at sql_parse.cc:896
#15 0x0000000000680cfa in do_command (thd=0x18e1d68) at sql_parse.cc:662
#16 0x000000000066ed2c in handle_one_connection (arg=0x18e1d68)
    at sql_connect.cc:1089
[19 Apr 2007 17:41] 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/24917

ChangeSet@1.2618, 2007-04-19 18:38:16+02:00, hakank@lu0011.wdf.sap.corp +5 -0
  New test case for failing Bug#27951.
[19 Apr 2007 19:48] Calvin Sun
May be related to bug#27277.
[20 Apr 2007 0:15] Christopher Powers
This is caused by RecordVersion::thaw() attempting to restore record data from the Serial Log without ensuring that the transaction associated with the record is valid.

If the thaw from the Serial fails or is othewise not possible, RecordVersion::thaw() restores the record from the data pages.

I modified RecordVersion:thaw() to 1) check for a null transaction, and 2) increment the transaction usecount prior to thawing from the Serial Log.
[21 Apr 2007 16:26] Kevin Lewis
Chris implemented, tested on Windows, and pushed a couple changesets to
fix this.  The basic change is to prevent a committed transaction from
being removed by the scavenger thread in the middle of thawing the
record from the serial log.  This is done by adding a useCount to the
Transaction during the thaw. The first changeset had a problem on Linux
and the second changeset solved the problem by thawing from the serial
log only if the transaction was not yet committed.  The third changeset
by Kevin goes back to the original solution of incrementing
Transaction::useCount with the addition of code in Transaction::commit
that prevents removal of the transaction while the useCount is > 1. 
This causes the transaction to be removed in the same place as before. 
 
Also a record is not thawed from the serial log after
Transaction::writePending == false.  This covers the time between
Transaction::commit() and writeComplete().
[21 Apr 2007 17:34] Hakan Küçükyılmaz
Now crashes while trying an assert():

Program received signal SIGSEGV, Segmentation fault.
0x00000000008dbc3c in Record::getEncodedValue (this=0x2aaaad682cb8, fieldId=0, 
    value=0x4087f670) at Record.cpp:643
643                             ASSERT(vector[index] < size);

(gdb) p vector
$1 = (USHORT *) 0x0

(gdb) bt
#0  0x00000000008dbc3c in Record::getEncodedValue (this=0x2aaaad682cb8, 
    fieldId=0, value=0x4087f670) at Record.cpp:643
#1  0x00000000008dc86a in Record::getValue (this=0x2aaaad682cb8, fieldId=0, 
    value=0x4087f670) at Record.cpp:313
#2  0x00000000008b1e41 in Index::makeKey (this=0x2aaaaad35d18, 
    record=0x2aaaad682cb8, key=0x4087fbc0) at Index.cpp:520
#3  0x00000000008b31b2 in Index::insert (this=0x2aaaaad35d18, 
    record=0x2aaaad682cb8, transaction=0x2aaaaacbbc28) at Index.cpp:183
#4  0x0000000000868554 in Table::insert (this=0x2aaaaad35aa0, 
    transaction=0x2aaaaacbbc28, stream=0x2aaaaac57708) at Table.cpp:2407
#5  0x0000000000853bf7 in StorageDatabase::insert (this=0x2aaaaacf8058, 
    connection=0x2aaaaacfb970, table=0x2aaaaad35aa0, stream=0x2aaaaac57708)
    at StorageDatabase.cpp:245
#6  0x0000000000858d87 in StorageTable::insert (this=0x2aaaaac56b90)
    at StorageTable.cpp:84
#7  0x000000000084e062 in NfsStorageTable::write_row (this=0x105e3e8, 
    buff=0x105e7e8 "��") at ha_falcon.cpp:856
#8  0x000000000077fe7e in handler::ha_write_row (this=0x105e3e8, 
    buf=0x105e7e8 "��") at handler.cc:3637
#9  0x00000000006ff05b in write_record (thd=0x1035048, table=0x104f6b8, 
    info=0x1050c50) at sql_insert.cc:1347
[25 Apr 2007 1:06] Hakan Küçükyılmaz
falcon_test_27951.test passes now.
[25 Apr 2007 3:38] Christopher Powers
The issue was that RecordVersion::thaw() was invoked during Transaction:commitRecords(), causing RecordVersion::transaction to be cleared during a restore from the Serial Log.

Kevin added a useCount check in Transaction::commit to guard against this, but if there are many records then the thaw will likely happen during commitRecords() anyway.

The fix was simple: save the transaction pointer, bump the ref count, then use the transaction pointer to thaw and to release the transaction.

I also changed RecordVersion::thaw() to restore from the Serial Log while transaction->writePending is still true. If writePending is false, then the record data has already been written to the data pages, so the record is restored with a fetch instead of from the Serial Log.
[26 Apr 2007 11:01] MC Brown
A note has been added to the 6.0.0 changelog.