Bug #39696 Assertion in Table.cpp (dup->state == recDeleted) fails during falcon_chill_thaw
Submitted: 27 Sep 2008 15:53 Modified: 13 Dec 2008 9:05
Reporter: John Embretsen Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Falcon storage engine Severity:S1 (Critical)
Version:6.0-falcon-team (6.0.8a) OS:Windows (Version 6.0.6001, Visual Studio 2008)
Assigned to: Christopher Powers CPU Architecture:Any
Tags: F_CHILL THAW, pb2, pushbuild, test failure

[27 Sep 2008 15:53] John Embretsen
Description:
From falcon_chill_thaw test output ("Pushbuild 2", Random Query Generator) for revid john.embretsen@sun.com-20080927075218-hwawm8ctbebpgyrc, win 
x86 max:

# 15:21:50 Query: UPDATE D AS X SET `int_nokey` = 225 WHERE X . `int_key` < 193 failed: 1205 Lock wait timeout exceeded; try restarting transaction
# 15:21:54 Query: INSERT INTO A ( `int_key` , `pk` ) VALUES ( 39 , 167 ) failed: 2013 Lost connection to MySQL server during query

From error log:
(...)
Table::fetchForUpdate: Update Conflict: TransId=1689, RecordNumber=29, Table TEST.C
Table::fetchForUpdate: Update Conflict: TransId=1689, RecordNumber=0, Table TEST.E
[Falcon] Error: assertion (dup->state == recDeleted) failed at line 2554 in file .\Table.cpp

080927 16:21:36 - mysqld got exception 0x80000003 ;
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=1048576
read_buffer_size=131072
max_used_connections=11
max_threads=151
thread_count=11
connection_count=11
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 59983 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x838a428
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...
00757D70    mysqld.exe!Error::debugBreak()[error.cpp:90]
00757E3E    mysqld.exe!Error::error()[error.cpp:73]
00757E89    mysqld.exe!Error::assertionFailed()[error.cpp:78]
00769454    mysqld.exe!Table::checkUniqueRecordVersion()[table.cpp:2554]
0076B745    mysqld.exe!Table::checkUniqueIndex()[table.cpp:2493]
0076C06A    mysqld.exe!Table::updateIndexes()[table.cpp:1213]
0076C91D    mysqld.exe!Table::update()[table.cpp:3163]
0075DC80    mysqld.exe!StorageDatabase::updateRow()[storagedatabase.cpp:690]
00757078    mysqld.exe!StorageTable::updateRow()[storagetable.cpp:141]
00750828    mysqld.exe!StorageInterface::update_row()[ha_falcon.cpp:1168]
00448664    mysqld.exe!handler::ha_update_row()[handler.cc:5245]
FFFFFFFF    ntdll.dll!VerSetConditionMask()
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 083C2CC8=UPDATE A AS X SET `pk` = 37 WHERE X . `int_key` > 12
thd->thread_id=11
thd->killed=NOT_KILLED

How to repeat:
Branch or checkout the mysql-test-extra-6.0 bazaar tree and run:

$ cd mysql-test\gentest
$ perl runall.pl \
 --basedir=path\to\mysql-6.0-falcon-team \
 --reporters=Deadlock,ErrorLog,Backtrace,Recovery,WinPackage \
 --mysqld=--loose-falcon-lock-wait-timeout=1 \
 --engine=Falcon \
 --grammar=conf/falcon_chill_thaw.yy \ 
 --queries=100000 \
 --mysqld=--falcon-index-chill-threshold=4K \ 
 --mysqld=--falcon-record-chill-threshold=4K \ 
 --duration=1200
[27 Sep 2008 16:18] John Embretsen
Attached full test log from failed test case.

Attachment: falcon_chill_thaw_log_win_bug39696.txt (text/plain), 85.98 KiB.

[24 Oct 2008 5:10] 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:58] 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.
[27 Oct 2008 18:29] Christopher Powers
This is an example of a failed record thaw.
[28 Oct 2008 8:09] Bugs System
Pushed into 6.0.8-alpha  (revid:cpowers@mysql.com-20081024053538-6y1ma8lydl93oxza) (version source revid:alik@mysql.com-20081028074021-o49ijs3x4pxj1gbm) (pib:5)
[7 Nov 2008 1:12] 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/58131

2905 Christopher Powers	2008-11-06
      Bug#39696, "Assertion in Table.cpp (dup->state == recDeleted) fails during falcon_chill_thaw"
      
      Fixed problems with savepoint rollbacks that prevented some chilled records from being committed.
[7 Nov 2008 2:41] Kevin Lewis
Code looks good, OK to push
[9 Nov 2008 1:48] 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/58261

2906 Christopher Powers	2008-11-08
      Bug#39696, "Assertion in Table.cpp (dup->state == recDeleted) fails during falcon_chill_thaw"
      
      The record chill operation sometimes generates SRLUpdateRecord entries in the serial
      log that have zero data length. This causes a corruption of the serial log.
      
      The total data length of the chilled records is known only after all of the records have
      been processed in SRLUpdateRecords::append(). If none of the record versions within
      a given savepoint are eligible to be chilled, the total data length of the serial log
      record will be zero.
      
      Even when there are zero bytes of data to commit to disk, SRLUpdateRecords::append() issues
      a serial log flush and forces the creation of a new serial log window. This creates a one-byte
      offset error in the serial log that ultimately results in a fatal assertion during gopher
      thread processing.
      
      To prevent this error, SRLUpdateRecords::append() now only flushes serial log records with a
      non-zero data length.
[20 Nov 2008 12:55] Bugs System
Pushed into 6.0.9-alpha  (revid:cpowers@mysql.com-20081109014458-kg3iluxnhcxkvosc) (version source revid:cpowers@mysql.com-20081109014458-kg3iluxnhcxkvosc) (pib:5)
[13 Dec 2008 9:05] MC Brown
No documentation needed (internal change only)