| Bug #41661 | Falcon assertion (ret) failed at line 3052 in file Table.cpp | ||
|---|---|---|---|
| Submitted: | 20 Dec 2008 22:04 | Modified: | 15 May 2009 13:40 |
| Reporter: | Philip Stoev | Email Updates: | |
| Status: | Closed | Impact on me: | |
| 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 | ||
[7 Mar 2009 14:51]
Philip Stoev
Rows: 10, max field size: 256; threads 8; queries: update, insert, delete To reproduce within 20 seconds on 20% of the test runs: $ 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 \ --mem \ --rows=10 \ --threads=8 \ --mysqld=--falcon-consistent=read=1 \ --varchar-length=256 \ --basedir=/build/bzr/6.0-falcon-team \ --mask=2094 \ --queries=100000000 \ --duration=900 \ --gendata=conf/varchar.zz \ --grammar=conf/varchar.yy Other crashes are possible with this test, however with sufficient patience the assertion this bug is about will be hit.
[7 Mar 2009 16:55]
Kevin Lewis
This is a case where Table::insertIntoTree() failed inadvertently. We are seeing this alot. In this case, it is in Table::insert(Transaction *transaction, Stream *stream) in the following code. // Do the actual insert transaction->addRecord(record); bool ret = insertIntoTree(record, NULL, recordNumber); inserted = true; insertIndexes(transaction, record); ASSERT(ret); record->state = recData; record->release(REC_HISTORY); See also; Bug#42185 & Bug#43298
[24 Mar 2009 0:38]
Hakan Küçükyılmaz
I could reproduce the assertion with DBT2 on walldorf: [Falcon] Error: assertion (ret) failed at line 3078 in file Table.cpp 090320 12:22:08 - mysqld got signal 6 ; 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=8388608 read_buffer_size=1048576 max_used_connections=16 max_threads=1601 thread_count=16 connection_count=16 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 4943687 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. thd: 0x2aab3c390bd0 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... stack_bottom = 0x4dee00e8 thread_stack 0x40000 /data0/work/mysql/mysql-6.0-falcon/sql/mysqld(my_print_stacktrace+0x2e) [0xabfe3e] /data0/work/mysql/mysql-6.0-falcon/sql/mysqld(handle_segfault+0x336) [0x65cc36] /lib64/libpthread.so.0 [0x372ae0de60] /lib64/libpthread.so.0(raise+0x2d) [0x372ae0dd3d] /data0/work/mysql/mysql-6.0-falcon/sql/mysqld(Error::error(char const*, ...)+0xf9) [0x8684d9] /data0/work/mysql/mysql-6.0-falcon/sql/mysqld(Table::insert(Transaction*, Stream*)+0xd8) [0x881c68] /data0/work/mysql/mysql-6.0-falcon/sql/mysqld(StorageTable::insert()+0x3d) [0x87479d] /data0/work/mysql/mysql-6.0-falcon/sql/mysqld(StorageInterface::write_row(unsigned char*)+0x6c) [0x8637bc] /data0/work/mysql/mysql-6.0-falcon/sql/mysqld(handler::ha_write_row(unsigned char*)+0x6f) [0x76e08f] /data0/work/mysql/mysql-6.0-falcon/sql/mysqld(write_record(THD*, TABLE*, st_copy_info*)+0x5d) [0x6f5cbd] /data0/work/mysql/mysql-6.0-falcon/sql/mysqld(mysql_insert(THD*, TABLE_LIST*, List<Item>&, List<List<Item> >&, List<Item>&, List<Item>&, enum_duplicates, bool)+0xa64) [0x6fade4] /data0/work/mysql/mysql-6.0-falcon/sql/mysqld(mysql_execute_command(THD*)+0x2d13) [0x66f8e3] /data0/work/mysql/mysql-6.0-falcon/sql/mysqld(mysql_parse(THD*, char const*, unsigned int, char const**)+0x23c) [0x672d4c] /data0/work/mysql/mysql-6.0-falcon/sql/mysqld(dispatch_command(enum_server_command, THD*, char*, unsigned int)+0x98d) [0x673afd] /data0/work/mysql/mysql-6.0-falcon/sql/mysqld(do_command(THD*)+0xc4) [0x674684] /data0/work/mysql/mysql-6.0-falcon/sql/mysqld(handle_one_connection+0xf4) [0x666174] /lib64/libpthread.so.0 [0x372ae062e7] /lib64/libc.so.6(clone+0x6d) [0x372a2ce3bd]
[30 Mar 2009 21:57]
Kevin Lewis
Philip reported that this problem cannot be repeated after the changes to create a TransactionState object and the addition of the CycleManager to protect doomed records until after all temporary stack pointers to them have gone away.
[2 Apr 2009 17:36]
Kevin Lewis
Hakan has reproduced this bug again running DBT2.
[Falcon] Error: assertion (ret) failed at line 3098 in file Table.cpp
Error::error(char const*, ...)
Table::insert(Transaction*, Stream*)
StorageDatabase::insert(Connection*, Table*, Stream*)
StorageTable::insert()
StorageInterface::write_row(unsigned char*)
handler::ha_write_row(unsigned char*)
write_record(THD*, TABLE*,st_copy_info*)
mysql_insert(THD*,TABLE_LIST*, List<Item>&, List<List<Item> >&,
List<Item>&, List<Item>&, enum_duplicates, bool)+0x994)
mysql_execute_command(THD*)+0x135d)
This is really a failure of the code to handle an unsuccessful call to insertIntoTree().
uint Table::insert(Transaction *transaction, Stream *stream)
{
. . .
bool ret = insertIntoTree(record, NULL, recordNumber);
inserted = true;
insertIndexes(transaction, record);
ASSERT(ret);
. . .
[6 Apr 2009 17:51]
Kevin Lewis
In this bug, a new record is inserted into a table. The slot in the Recordleaf that is used is controled by the record number chosen. This is assigned by Dbb::insertStub() which uses an exclusive lock on the Section::syncInsert. This syncInsert lock serializes all free record numbers added by Section::expungeRecord() and used again by Section::insertStub(), or reserved by Section::reserveRecordNumber(). But what is a record number that is still in use is returned from Section::insertStub()? Section::expungeRecord() provides these free record numbers, and for Record Locator Page sections, this is always called after the slot in the RecordTree has been set to NULL. Always except... in RecordLeaf::retireRecords. This function calls Record->retire first, and then sets the RecordLeaf::records[slot] to NULL. It was assumed that an exclusive lock on RecordLeaf::syncObject would make it OK to provide the record number to the Section (RecordLocatorPage) first and then clear the RecordLeaf. But most calls to Table::insertIntotree() do not actually get any lock on RecordLeaf::syncObject. This means that when the scavenger is retiring records, it often releases the record number to be reused and then sets the slot in the recordLeaf to NULL. In the mean time, any amount of stuff could happen. For this bug, insertStub returns a record number, the insert calls insertIntoTree, which fails because the that slot in the RecordLeaf is not yet NULL. I need to rearrange RecordLeaf::retireRecords so that it sets the slot to NULL first, and then releases the record number to be reused.
[7 Apr 2009 14:32]
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/71557 3105 Kevin Lewis 2009-04-07 Bug#41661 - Table::insertIntoTree could fail during a Table::insert. This should not happen since Dbb::insertStub should have returned a record number that was free. Nobody else should have been messing with that slot in the RecordLeaf. The problem was in RecordLeaf::retireRecords. This function called RecordVersion::retire which then called expungeRecord. This makes the record number free to use again by any other thread. It did this with an exclusive lock on the RecordLeaf, but Table::insertIntoTree often does not get any lock on RecordLeaf when it calls RecordLeaf::store. So a free record number is reused in Table::insert before the slot has been set to NULL by RecordLeaf::retireRecords. That is why Table::insertIntoTree fails. It expects the slot to be NULL. Another problem fixed is that the first of the two Table::insert functions did not check the return value of insertIntoTree at all. This would have propogated the error further since there would be nothing in the RecordTree slot after the insert. Another problem fixed in RecordLeaf::retireRecords is with this statement; if (record && recordScavenge->canBeRetired(record)) The problem is with incrementing the 'count' integer. If it is zero after stepping through the RecordLeaf, then it is assumed that the RecordLeaf is empty and can be retired. But this 'if' statement gets the wrong result. If the RecordLeaf is full of newer records that cannot yet be retired, then this count will remain zero. The emptySections bitmap will be set for this RecordLeaf. And later, in Table::retireRecords, it will attempt to retire these sections. But finding records in them, it will just waste a lot of time. I changed this code to be accurate in determining if the RecordLeaf is indead empty before setting the bit in Table::emptySections. Record::retire and RecordVersion::retire now only retire records. The more thorough tests for whether a record can be retired is collected into RecordScavenge::canBeRetired. Also, instead of just setting the slot in RecordLeaf to NULL directly, I now use a COMPARE_EXCHANGE_POINTER() just like every other place where this location is changed. Then if it fails for any reason, we will not retire that record. One legitimate reason that this could fail is when this record is determined that it canBeRetired, but immediately after that, a client thread does a fetchForUpdate, adding a lockRecord. Since the 'count' integer is incremented only within it, a RecordLeaf that does not have any
[9 Apr 2009 14:46]
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/71790 3114 Kevin Lewis 2009-04-09 Bug#41661 - A mistake was faound in RecordLeaf::retireRecords. It makes a call to Record::retire() first and then calls record->getMemUsage(). It should do it the other way around. In addition, I found that the scavenger thread should also have a CycleLock for each table tht it prunes or retires because these activities can look at priorRecords periodically.
[15 Apr 2009 17:00]
Bugs System
Pushed into 6.0.11-alpha (revid:hky@sun.com-20090415164923-9arx29ye5pzxd4zf) (version source revid:kevin.lewis@sun.com-20090409144517-vor0khtrwnlqltb2) (merge vers: 6.0.11-alpha) (pib:6)
[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.
Description: When executing a transactional workload with the Random Query Generator, Falcon asserted as follows: #7 0x00000000009ccc47 in Error::assertionFailed (text=0xe04267 "ret", fileName=0xe03145 "Table.cpp", line=3052) at Error.cpp:78 #8 0x000000000097d561 in Table::insert (this=0x7fbcfd3775f8, transaction=0x7fbcfd420bd8, stream=0x7fbcfd3aaa68) at Table.cpp:3052 #9 0x0000000000961419 in StorageDatabase::insert (this=0x7fbcfd028210, connection=0x7fbcfd083de0, table=0x7fbcfd3775f8, stream=0x7fbcfd3aaa68) at StorageDatabase.cpp:266 #10 0x00000000009685c3 in StorageTable::insert (this=0x7fbcfd3a54c8) at StorageTable.cpp:109 #11 0x000000000095a999 in StorageInterface::write_row (this=0x258dcf0, buff=0x258dfb0 "Ыэ") at ha_falcon.cpp:1132 #12 0x00000000008005e7 in handler::ha_write_row (this=0x258dcf0, buf=0x258dfb0 "Ыэ") at handler.cc:5369 #13 0x0000000000768f46 in write_record (thd=0x2546898, table=0x258d408, info=0x26032d0) at sql_insert.cc:1609 #14 0x0000000000769309 in select_insert::send_data (this=0x2603298, values=@0x7fbcf89ce358) at sql_insert.cc:3165 #15 0x0000000000732826 in end_send (join=0x7fbcf89cc940, join_tab=0x7fbcf89d1060, end_of_records=false) at sql_select.cc:14754 #16 0x000000000073e1dc in evaluate_join_record (join=0x7fbcf89cc940, join_tab=0x7fbcf89d0dc0, error=0) at sql_select.cc:13981 #17 0x000000000073e46e in sub_select (join=0x7fbcf89cc940, join_tab=0x7fbcf89d0dc0, end_of_records=false) at sql_select.cc:13733 #18 0x000000000074d27f in do_select (join=0x7fbcf89cc940, fields=0x7fbcf89ce358, table=0x0, procedure=0x0) at sql_select.cc:13479 #19 0x0000000000762341 in JOIN::exec (this=0x7fbcf89cc940) at sql_select.cc:2845 #20 0x000000000075d08c in mysql_select (thd=0x2546898, rref_pointer_array=0x2548a68, tables=0x2602950, wild_num=0, fields=@0x2548988, conds=0x2603098, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=3491514880, result=0x2603298, unit=0x2548428, select_lex=0x2548880) at sql_select.cc:3035 #21 0x0000000000762660 in handle_select (thd=0x2546898, lex=0x2548388, result=0x2603298, setup_tables_done_option=1073741824) at sql_select.cc:301 #22 0x00000000006ce457 in mysql_execute_command (thd=0x2546898) at sql_parse.cc:3167 #23 0x00000000006d37d1 in mysql_parse (thd=0x2546898, inBuf=0x2601bf0 "INSERT INTO `table10_falcon_int_autoinc` ( `int_key` , `int` ) SELECT `int` , `int_key` FROM `table10_falcon_int_autoinc` WHERE `pk` > 10 LIMIT 1", length=145, found_semicolon=0x7fbca44f3f00) at sql_parse.cc:5732 #24 0x00000000006d43bc in dispatch_command (command=COM_QUERY, thd=0x2546898, packet=0x25fcb49 " INSERT INTO `table10_falcon_int_autoinc` ( `int_key` , `int` ) SELECT `int` , `int_key` FROM `table10_falcon_int_autoinc` WHERE `pk` > 10 LIMIT 1 ", packet_length=147) at sql_parse.cc:1007 #25 0x00000000006d58e5 in do_command (thd=0x2546898) at sql_parse.cc:690 #26 0x00000000006c3a69 in handle_one_connection (arg=0x2546898) at sql_connect.cc:1154 #27 0x000000315b0073da in start_thread () from /lib64/libpthread.so.0 #28 0x000000315a4e627d in clone () from /lib64/libc.so.6 How to repeat: If this is repeatable, a test case will be provided.