Bug #43298 Falcon assertion record->recordNumber >= 0 in Transaction::addRecord
Submitted: 2 Mar 2009 8:30 Modified: 15 May 2009 13:25
Reporter: Philip Stoev Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Falcon storage engine Severity:S1 (Critical)
Version:6.0-falcon-team OS:Any
Assigned to: Kevin Lewis CPU Architecture:Any
Tags: F_RECORD TREE

[2 Mar 2009 8:30] Philip Stoev
Description:
When executing a concurrent combinations.yy transactional workload, Falcon asserted as follows:

#7  0x00000000009e775b in Error::assertionFailed (text=0xe443db "record->recordNumber >= 0", fileName=0xe43c70 "Transaction.cpp", line=590) at Error.cpp:78
#8  0x00000000009a526d in Transaction::addRecord (this=0x7f01c85f0cc0, record=0x7f01c8336b78) at Transaction.cpp:590
#9  0x0000000000993a11 in Table::fetchForUpdate (this=0x7f01c8a17de8, transaction=0x7f01c85f0cc0, source=0x7f01c834fd00, usingIndex=false) at Table.cpp:3539
#10 0x000000000097b02d in StorageDatabase::nextRow (this=0x7f01c8659208, storageTable=0x7f019c04f898, recordNumber=711, lockForUpdate=true)
    at StorageDatabase.cpp:289
#11 0x0000000000982305 in StorageTable::next (this=0x7f019c04f898, recordNumber=0, lockForUpdate=true) at StorageTable.cpp:158
#12 0x0000000000972703 in StorageInterface::rnd_next (this=0x7f019c00fd80, buf=0x7f019c036710 "ЪЪЪ") at ha_falcon.cpp:646
#13 0x000000000080e9a7 in rr_sequential (info=0x7f01a39464b0) at records.cc:390
#14 0x000000000079a62d in mysql_delete (thd=0x7f01c4eb2758, table_list=0x3c598c8, conds=0x3c5a0a0, order=0x7f01c4eb46b0, limit=1, options=0,
    reset_auto_increment=false) at sql_delete.cc:296
#15 0x00000000006d7e93 in mysql_execute_command (thd=0x7f01c4eb2758) at sql_parse.cc:3253
#16 0x00000000006dcedd in mysql_parse (thd=0x7f01c4eb2758,
    inBuf=0x3c596c0 "DELETE FROM `table100_falcon_int_autoinc` WHERE `int_unsigned_key` <= '20030506020232'  LIMIT 1", length=95,
    found_semicolon=0x7f01a3947f00) at sql_parse.cc:5752
#17 0x00000000006ddac8 in dispatch_command (command=COM_QUERY, thd=0x7f01c4eb2758,
    packet=0x7f01c4ebd059 "DELETE FROM `table100_falcon_int_autoinc` WHERE `int_unsigned_key` <= '20030506020232'  LIMIT 1", packet_length=95)
    at sql_parse.cc:1009
#18 0x00000000006deff1 in do_command (thd=0x7f01c4eb2758) at sql_parse.cc:691
#19 0x00000000006ccf71 in handle_one_connection (arg=0x7f01c4eb2758) at sql_connect.cc:1146
#20 0x000000315b0073da in start_thread () from /lib64/libpthread.so.0
#21 0x000000315a4e627d in clone () from /lib64/libc.so.6

How to repeat:
  perl runall.pl    --engine=Falcon   --reporters=Deadlock,ErrorLog,Backtrace,Recovery   --mysqld=--loose-falcon-lock-wait-timeout=1   --mysqld=--loose-innodb-lock-wait-timeout=1   --mysqld=--log-output=none   --mysqld=--skip-safemalloc   --mysqld=--falcon-page-size=4K  --rows=100 --threads=16 --mysqld=--falcon-use-deferred-index-hash=1   --basedir=/build/bzr/6.0-falcon-team   --mask=57595   --queries=100000000   --duration=900   --gendata=conf/combinations.zz  --grammar=conf/combinations.yy
[2 Mar 2009 8:40] Philip Stoev
To repeat within 10 seconds of test runtime:

$ perl runall.pl \
  --engine=Falcon \
  --mysqld=--loose-falcon-lock-wait-timeout=1 \
  --mysqld=--loose-innodb-lock-wait-timeout=1 \
  --mysqld=--log-output=none \
  --mysqld=--skip-safemalloc \
  --mysqld=--falcon-page-size=4K \
  --rows=100 \
  --threads=16 \
  --basedir=/build/bzr/6.0-falcon-team \
  --mask=57595 \
  --queries=100000000 \
  --duration=900 \
  --gendata=conf/combinations.zz \
  --grammar=conf/combinations.yy
[5 Mar 2009 10:35] Philip Stoev
(gdb) print * record
$3 = {<Record> = {_vptr.Record = 0xe54290, data = {record = 0x0}, useCount = 3, format = 0x7fc034a56300, recordNumber = -1, size = 112, generation = 1,
    highWater = -13108, encoding = 0 '\0', state = 4 '\004'}, priorVersion = 0x7fc017a60360, virtualOffset = 0, transaction = 0x7fc01ec13b30,
  nextInTrans = 0xcccccccccccccccc, prevInTrans = 0xcccccccccccccccc, transactionId = 2412, savePointId = 4, superceded = false}
[5 Mar 2009 10:44] Kevin Lewis
Bug#42185 is possibly similar in that it is the ASSERT two lines down.
[18 Mar 2009 15:47] Jim Starkey
Interestingly enough, on Windows, it crashes in the server

>	mysqld.exe!_NMSG_WRITE(int rterrnum=10)  Line 195	C
 	mysqld.exe!abort()  Line 44 + 0x7	C
 	mysqld.exe!_assert(const char * expr=0x00b0e7ac, const char * filename=0x00b0e79c, unsigned int lineno=5485)  Line 306	C
 	mysqld.exe!handler::ha_reset()  Line 5485 + 0x32	C++
 	mysqld.exe!close_thread_table(THD * thd=0x015c7120, TABLE * * table_ptr=0x015c716c)  Line 1517	C++
 	mysqld.exe!close_open_tables(THD * thd=0x015c7120)  Line 1228 + 0x14	C++
 	mysqld.exe!close_thread_tables(THD * thd=0x015c7120, bool skip_mdl=false)  Line 1476 + 0x9	C++
 	mysqld.exe!dispatch_command(enum_server_command command=COM_QUERY, THD * thd=0x015c7120, char * packet=0x015be941, unsigned int packet_length=72)  Line 1410 + 0xb	C++
 	mysqld.exe!do_command(THD * thd=0x015c7120)  Line 691 + 0x1b	C++
 	mysqld.exe!handle_one_connection(void * arg=0x015c7120)  Line 1146 + 0x9	C++
 	mysqld.exe!pthread_start(void * p=0x015bc8a8)  Line 61 + 0x9	C
 	mysqld.exe!_threadstartex(void * ptd=0x015b7f60)  Line 241 + 0xd	C
 	kernel32.dll!7c80b713()
[18 Mar 2009 15:54] Philip Stoev
The server crash is one of those catch-all asserts that check the thread after processing each query. Usually hitting those asserts indicates a problem in the optimizer or the server runtime.
[30 Mar 2009 22:07] Kevin Lewis
Philip reported that this problem cannot be repeated after 
the changes the following changes were added;
1) Olav created a TransactionState object that outlives the 
   Transaction
2) A CycleManager was added to protect doomed records until 
   after all temporary stack pointers to them have gone away.
[15 May 2009 13:25] MC Brown
Internal/test fix only. No changelog entry required.
[15 May 2009 13:40] MC Brown
A note have been added to the 6.0.11 changelog: 

The Falcon CycleManager has been updated, which addresses a number of issues when examining records in various transaction states and their visisbility/isolation in relation to other threads.