| Bug #35255 | falcon_bug_22165.test fails with debug builds | ||
|---|---|---|---|
| Submitted: | 12 Mar 2008 21:39 | Modified: | 15 May 2009 15:56 |
| Reporter: | Hakan Küçükyılmaz | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: Falcon storage engine | Severity: | S3 (Non-critical) |
| Version: | 6.0.4 | OS: | Any |
| Assigned to: | Vladislav Vaintroub | CPU Architecture: | Any |
| Tags: | crash, F_PAGE IO, pb2, pushbuild, sporadic, test failure | ||
[12 Mar 2008 21:39]
Hakan Küçükyılmaz
[13 Mar 2008 13:27]
MySQL Verification Team
Thank you for the bug report. I wasn't able to repeat on FC 8.0: TEST RESULT TIME (ms) ------------------------------------------------------- falcon.falcon_bug_22165 [ pass ] 60109 ------------------------------------------------------- Stopping All Servers All 1 tests were successful. The servers were restarted 1 times Spent 60.109 of 62 seconds executing testcases [miguel@mira mysql-test]$ Any clue?. Thanks in advance.
[13 Apr 2008 23:00]
Bugs System
No feedback was provided for this bug for over a month, so it is being suspended automatically. If you are able to provide the information that was originally requested, please do so and change the status of the bug back to "Open".
[29 Sep 2008 21:50]
Hakan Küçükyılmaz
Run it > 100 times Saving snapshot of installed databases ======================================================= TEST RESULT TIME (ms) ------------------------------------------------------- falcon.falcon_bug_22165 [ pass ] 7161 falcon.falcon_bug_22165 [ pass ] 6823 falcon.falcon_bug_22165 [ pass ] 7290 falcon.falcon_bug_22165 [ pass ] 6884 falcon.falcon_bug_22165 [ pass ] 10960 falcon.falcon_bug_22165 [ pass ] 7535 falcon.falcon_bug_22165 [ pass ] 7218 falcon.falcon_bug_22165 [ pass ] 7886 falcon.falcon_bug_22165 [ pass ] 9275 falcon.falcon_bug_22165 [ pass ] 7775 falcon.falcon_bug_22165 [ pass ] 7602 falcon.falcon_bug_22165 [ pass ] 10805 falcon.falcon_bug_22165 [ pass ] 7310 falcon.falcon_bug_22165 [ pass ] 7773 falcon.falcon_bug_22165 [ pass ] 8509 falcon.falcon_bug_22165 [ pass ] 11615 falcon.falcon_bug_22165 [ pass ] 7004 falcon.falcon_bug_22165 [ pass ] 8335 falcon.falcon_bug_22165 [ pass ] 10693 falcon.falcon_bug_22165 [ pass ] 7958 falcon.falcon_bug_22165 [ pass ] 8552 falcon.falcon_bug_22165 [ pass ] 8050 falcon.falcon_bug_22165 [ pass ] 8990 falcon.falcon_bug_22165 [ pass ] 8001 falcon.falcon_bug_22165 [ pass ] 7326 falcon.falcon_bug_22165 [ pass ] 11473 falcon.falcon_bug_22165 [ pass ] 7636 falcon.falcon_bug_22165 [ pass ] 7706 falcon.falcon_bug_22165 [ pass ] 8276 falcon.falcon_bug_22165 [ pass ] 8285 falcon.falcon_bug_22165 [ pass ] 7846 falcon.falcon_bug_22165 [ pass ] 7580 falcon.falcon_bug_22165 [ pass ] 11578 falcon.falcon_bug_22165 [ pass ] 7720 falcon.falcon_bug_22165 [ pass ] 8935 falcon.falcon_bug_22165 [ pass ] 8237 ... ... ... falcon.falcon_bug_22165 [ pass ] 11597 falcon.falcon_bug_22165 [ pass ] 11293 falcon.falcon_bug_22165 [ pass ] 10734 falcon.falcon_bug_22165 [ pass ] 9543 falcon.falcon_bug_22165 [ pass ] 9243 falcon.falcon_bug_22165 [ pass ] 8741 falcon.falcon_bug_22165 [ pass ] 10460 falcon.falcon_bug_22165 [ pass ] 8431 falcon.falcon_bug_22165 [ pass ] 9735 falcon.falcon_bug_22165 [ pass ] 10228 falcon.falcon_bug_22165 [ pass ] 9360 falcon.falcon_bug_22165 [ pass ] 10809 falcon.falcon_bug_22165 [ pass ] 10025 falcon.falcon_bug_22165 [ pass ] 8731 falcon.falcon_bug_22165 [ pass ] 10228 falcon.falcon_bug_22165 [ pass ] 8093 falcon.falcon_bug_22165 [ pass ] 9298 falcon.falcon_bug_22165 [ pass ] 9634 falcon.falcon_bug_22165 [ pass ] 11351 falcon.falcon_bug_22165 [ pass ] 9135 falcon.falcon_bug_22165 [ pass ] 9562 falcon.falcon_bug_22165 [ pass ] 9657 falcon.falcon_bug_22165 [ pass ] 8531 falcon.falcon_bug_22165 [ pass ] 9536 falcon.falcon_bug_22165 [ pass ] 13714 falcon.falcon_bug_22165 [ pass ] 8333 falcon.falcon_bug_22165 [ pass ] 9521 falcon.falcon_bug_22165 [ pass ] 13898 falcon.falcon_bug_22165 [ pass ] 10196 falcon.falcon_bug_22165 [ pass ] 8498 falcon.falcon_bug_22165 [ pass ] 12276 falcon.falcon_bug_22165 [ pass ] 9884 falcon.falcon_bug_22165 [ pass ] 8819 falcon.falcon_bug_22165 [ pass ] 10204 falcon.falcon_bug_22165 [ pass ] 9212 falcon.falcon_bug_22165 [ pass ] 8587 falcon.falcon_bug_22165 [ pass ] 10371 falcon.falcon_bug_22165 [ pass ] 8687 falcon.falcon_bug_22165 [ pass ] 8225 falcon.falcon_bug_22165 [ pass ] 10933 falcon.falcon_bug_22165 [ pass ] 9592 falcon.falcon_bug_22165 [ pass ] 9268 falcon.falcon_bug_22165 [ pass ] 13941 falcon.falcon_bug_22165 [ pass ] 8995 falcon.falcon_bug_22165 [ pass ] 11288 falcon.falcon_bug_22165 [ pass ] 11245 falcon.falcon_bug_22165 [ pass ] 10973 falcon.falcon_bug_22165 [ pass ] 8945 falcon.falcon_bug_22165 [ pass ] 10138 falcon.falcon_bug_22165 [ pass ] 9150 falcon.falcon_bug_22165 [ pass ] 9730 falcon.falcon_bug_22165 [ pass ] 10113 falcon.falcon_bug_22165 [ pass ] 10902 falcon.falcon_bug_22165 [ pass ] 11433 falcon.falcon_bug_22165 [ fail ] mysqltest: At line 65: query 'reap' failed: 2013: Lost connection to MySQL server during query The result from queries just before the failure was: < snip > CREATE PROCEDURE p1 () begin declare v int default 0; declare continue handler for sqlexception begin declare continue handler for sqlexception begin end; ALTER TABLE t1 MODIFY COLUMN c timestamp; end; SET TRANSACTION ISOLATION LEVEL READ COMMITTED; while v < 10 do START TRANSACTION; INSERT INTO t1 (a, b) VALUES (v, 'a'); UPDATE t1 SET c = current_timestamp WHERE a = v; IF (v < 5) THEN COMMIT; ELSE ROLLBACK; END IF; SET v = v + 1; end while; end//
[29 Sep 2008 21:52]
Hakan Küçükyılmaz
Stack trace is /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(my_print_stacktrace+0x2e)[0xa62a98] /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(handle_segfault+0x25c)[0x66f7c5] /lib/libpthread.so.0[0x7ffb24048a90] /lib/libpthread.so.0(raise+0x2b)[0x7ffb2404894b] /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(Error::debugBreak()+0xe)[0x8b7568] /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(Error::error(char const*, ...)+0xea)[0x8b7658] /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(Error::assertionFailed(char const*, char const*, int)+0x19)[0x8b76bb] /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(Section::getSectionPage(Dbb*, int, int, LockType, unsigned int)+0x97)[0x8ecf6f] /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(Section::getSectionPage(int, LockType, unsigned int)+0x163)[0x8ed3b1] /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(Section::insertStub(unsigned int)+0x15c)[0x8edf40] /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(Dbb::insertStub(Section*, Transaction*)+0x19)[0x8af2d5] /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(Table::insert(Transaction*, Stream*)+0x9d)[0x88290b] /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(StorageDatabase::insert(Connection*, Table*, Stream*)+0x2a)[0x871d1a] /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(StorageTable::insert()+0x39)[0x8761c9] /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(StorageInterface::write_row(unsigned char*)+0xd7)[0x86d54b] /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(handler::ha_write_row(unsigned char*)+0xac)[0x769e74] /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(mysql_alter_table(THD*, char*, char*, st_ha_create_information*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool)+0x2b48)[0x787e98] /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(mysql_execute_command(THD*)+0x5609)[0x681572] /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(sp_instr_stmt::exec_core(THD*, unsigned int*)+0x1c)[0x7dc496] /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(sp_lex_keeper::reset_lex_and_exec_core(THD*, unsigned int*, bool, sp_instr*)+0x151)[0x7dc6b1] /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(sp_instr_stmt::execute(THD*, unsigned int*)+0x114)[0x7e1a28] /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(sp_head::execute(THD*)+0x4fa)[0x7dfee6] /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(sp_head::execute_procedure(THD*, List<Item>*)+0x4d1)[0x7e0849] /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(mysql_execute_command(THD*)+0x458f)[0x6804f8] /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(mysql_parse(THD*, char const*, unsigned int, char const**)+0x176)[0x683518] /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(dispatch_command(enum_server_command, THD*, char*, unsigned int)+0x79e)[0x683e11] /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(do_command(THD*)+0x1f9)[0x684d66] /home/hakan/work/mysql/mysql-6.0-falcon-team/sql/mysqld(handle_one_connection+0x103)[0x67781d] /lib/libpthread.so.0[0x7ffb24040fc7] /lib/libc.so.6(clone+0x6d)[0x7ffb22b9c7cd] [Falcon] Error: assertion (page->pageType == PAGE_sections || page->pageType == 0) failed at line 198 in file Section.cpp
[1 Oct 2008 9:39]
John Embretsen
Apparently same test failure in Pushbuild logged as Bug #39452 "Test falcon_bug_22165 fails intermittently (crash)".
[1 Oct 2008 9:53]
John Embretsen
Error message seen in Pushbuild (see Bug#39452 - Duplicate): mysqltest: At line 65: query 'reap' failed: 2013: Lost connection to MySQL server during query Seen on various platforms including Solaris and Linux.
[25 Nov 2008 17:39]
Kevin Lewis
Vlad, Please see if you can catch this in the debugger. It is a wrong page type problem. [Falcon] Error: assertion (page->pageType == PAGE_sections || page->pageType == 0) failed at line 198 in file Section.cpp
[25 Nov 2008 21:35]
Olav Sandstå
I was able to get a core file for this multiple times last week and filed bug#40852 (which is likely a duplicate of this bug). If it is at any help, the content of the *page object is available in bug#40852.
[25 Nov 2008 22:07]
Hakan Küçükyılmaz
[19 Nov 14:18] Olav Sandstaa
Description:
When running falcon_bug_22165 I have seen the following assert several times when running
against Falcon checked out from the mysql-6.0-falcon-team branch:
Error: assertion (page->pageType == PAGE_sections || page->pageType == 0) failed at line
198 in file Section.cpp
The call stack from the crash is:
[13] Error::assertionFailed(text = 0x158d510 "page->pageType == PAGE_sections ||
page->pageType == 0", fileName = 0x158d547 "Section.cpp", line = 198), line 78 in
"Error.cpp"
[14] Section::getSectionPage(dbb = 0x1d16840, root = 4, sequence = 0, requestedLockType
= Exclusive, transId = 268U), line 198 in "Section.cpp"
[15] Section::getSectionPage(this = 0x1d51d98, sequence = 0, lockType = Exclusive,
transId = 268U), line 1416 in "Section.cpp"
[16] Section::insertStub(this = 0x1d51d98, transId = 268U), line 348 in "Section.cpp"
[17] Dbb::insertStub(this = 0x1d16840, section = 0x1d51d98, transaction = 0x25400b8),
line 306 in "Dbb.cpp"
[18] Table::insert(this = 0x2547c70, transaction = 0x25400b8, stream = 0x2547158), line
3041 in "Table.cpp"
[19] StorageDatabase::insert(this = 0x1d112d8, connection = 0x1d51728, table =
0x2547c70, stream = 0x2547158), line 266 in "StorageDatabase.cpp"
[20] StorageTable::insert(this = 0x2541bb8), line 109 in "StorageTable.cpp"
[21] StorageInterface::write_row(this = 0x3d193d8, buff = 0x3d1a768 "ü"), line 1127 in
"ha_falcon.cpp"
[22] handler::ha_write_row(this = 0x3d193d8, buf = 0x3d1a768 "ü"), line 5362 in
"handler.cc"
[23] copy_data_between_tables(from = 0x3d13270, to = 0x3d17bc0, create = CLASS, ignore =
false, order_num = 0, order = (nil), copied = 0xfffffd7ffd6e1788, deleted =
0xfffffd7ffd6e1780, keys_onoff = LEAVE_AS_IS, error_if_not_empty = false), line 7441 in
"sql_table.cc"
[24] mysql_alter_table(thd = 0x3ccb240, new_db = 0x3ce36d8 "test", new_name = 0x3ce93c8
"t1", create_info = 0xfffffd7ffd6e3198, table_list = 0x3ce9410, alter_info =
0xfffffd7ffd6e30f8, order_num = 0, order = (nil), ignore = false), line 7042 in
"sql_table.cc"
[25] mysql_execute_command(thd = 0x3ccb240), line 2761 in "sql_parse.cc"
[26] sp_instr_stmt::exec_core(this = 0x3ce9a90, thd = 0x3ccb240, nextp =
0xfffffd7ffd6e4688), line 2910 in "sp_head.cc"
[27] sp_lex_keeper::reset_lex_and_exec_core(this = 0x3ce9ad0, thd = 0x3ccb240, nextp =
0xfffffd7ffd6e4688, open_tables = false, instr = 0x3ce9a90), line 2734 in "sp_head.cc"
[28] sp_instr_stmt::execute(this = 0x3ce9a90, thd = 0x3ccb240, nextp =
0xfffffd7ffd6e4688), line 2847 in "sp_head.cc"
[29] sp_head::execute(this = 0x3ce3238, thd = 0x3ccb240), line 1241 in "sp_head.cc"
[30] sp_head::execute_procedure(this = 0x3ce3238, thd = 0x3ccb240, args = 0x3ccd6a0),
line 1972 in "sp_head.cc"
[31] mysql_execute_command(thd = 0x3ccb240), line 4216 in "sql_parse.cc"
[32] mysql_parse(thd = 0x3ccb240, inBuf = 0x3cb2468 "call p1()", length = 9U,
found_semicolon = 0xfffffd7ffd6e7be8), line 5719 in "sql_parse.cc"
[33] dispatch_command(command = COM_QUERY, thd = 0x3ccb240, packet = 0x3cbccb1 "call
p1();", packet_length = 10U), line 1006 in "sql_parse.cc"
[34] do_command(thd = 0x3ccb240), line 689 in "sql_parse.cc"
[35] handle_one_connection(arg = 0x3ccb240), line 1156 in "sql_connect.cc"
[36] _thr_setup(0x0, 0x0, 0x0, 0x0, 0x0, 0x0), at 0xfffffd7fff10fd7b
[37] _lwp_start(0x0, 0x0, 0x0, 0x0, 0x0, 0x0), at 0xfffffd7fff10ffb0
Information about what the page object:
(dbx) print -r *page
*page = {
SectionPage::Page::pageType = 4
SectionPage::Page::checksum = 0
SectionPage::Page::pageNumber = 4
SectionPage::Page::pageUnused = 0
SectionPage::section = 4
SectionPage::sequence = 0
SectionPage::level = 103
SectionPage::flags = 0
SectionPage::pages = (5)
}
[13 Jan 2009 20:46]
Vladislav Vaintroub
I traces the history of the page in question (this is Table::dataSection::root). It appears that this page was deleted by gopher thread and reallocated later (as PAGE_inventoryPage). So for me it looks like dataSection::root was wrong and pointed to a page that was about to be deleted. Reallocation stacktrace. [1] Bdb::setPageHeader [2] Cache::fakePage [3] Dbb::fakePage [4] PageInventoryPage::allocPage [5] Dbb::allocPage [6] Section::insertStub [7] Dbb::insertStub [8] Table::insert [9] StorageDatabase::insert [10] StorageTable::insert [11] StorageInterface::write_row [12] handler::ha_write_row [13] copy_data_between_tables [14] mysql_alter_table [15] mysql_execute_command [16] sp_instr_stmt::exec_core [17] sp_lex_keeper::reset_lex_and_exec_core [18] sp_instr_stmt::execute Release stacktrace [1] Bdb::setPageHeader [2] Dbb::freePage [3] Section::deleteSectionLevel [4] Section::deleteSection [5] SRLDropTable::commit [6] SerialLogTransaction::commit [7] SerialLogTransaction::doAction [8] Gopher::gopherThread [9] Gopher::gopherThread [10] Thread::thread [11] Thread::thread
[15 Jan 2009 9:24]
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/63324 2970 Vladislav Vaintroub 2009-01-15 Bug#35255 : test falcon_bug_22165 fails sporadically. Problem : Crashes happen in a concurrent workload with inserts/create table/drop table, or insert/alter table. The reason for assertions is a race condition in Dbb::findSection() function, that is calledon the first insert() after table is created ot altered. When 2 threads are looking for the same section in Dbb::sections hashtable at the very same time and do not find it , they will insert 2 equal entries into the table. One entry will be deleted, when table is dropped. Another entry will stay and will with high probability become invalid when section for this table is reused (invalid means root page does not match sectionId). In this case, next access to section will fail with an assert. The fix is to synchronize access to the Dbb::section hashtable with a mutex .There are very few calls to Dbb::findSection in normal case, so synchronization will not introduce performance losses.
[13 Feb 2009 15:53]
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/66246 3016 Vladislav Vaintroub 2009-02-13 Bug#35255 : test falcon_bug_22165 fails sporadically. Problem : Crashes happen in a concurrent workload with inserts/create table/drop table, or insert/alter table. The reason for assertions is a race condition in Dbb::findSection() function, that is called on the first insert() after table is created ot altered. When 2 threads are looking for the same section in Dbb::sections hashtable at the very same time and do not find it , they will insert 2 equal entries into the table. One entry will be deleted, when table is dropped. Another entry will stay and will with high probability become invalid when section for this table is reused (invalid means root page does not match sectionId). In this case, next access to section will fail with an assert. The fix is to synchronize access to the Dbb::section hashtable with a mutex .There are very few calls to Dbb::findSection in normal case, so synchronization will not introduce performance losses. modified: storage/falcon/Dbb.cpp storage/falcon/Dbb.h === modified file 'storage/falcon/Dbb.cpp' --- a/storage/falcon/Dbb.cpp 2009-02-10 22:50:04 +0000 +++ b/storage/falcon/Dbb.cpp 2009-02-13 15:53:28 +0000 @@ -372,6 +372,8 @@ Section* Dbb::findSection(int32 sectionI int slot = sectionId % SECTION_HASH_SIZE; Section *section; + Sync sync (§ionsMutex, "Dbb::findSection"); + sync.lock(Exclusive); for (section = sections [slot]; section; section = section->hash) if (section->sectionId == sectionId) return section; @@ -619,7 +621,10 @@ void Dbb::deleteSection(int32 sectionId, Section::deleteSection (this, sectionId, transId); Section *section; - + + Sync sync(§ionsMutex, "Dbb::deleteSection"); + sync.lock(Exclusive); + for (Section **ptr = sections + slot; (section = *ptr); ptr = §ion->hash) if (section->sectionId == sectionId) { === modified file 'storage/falcon/Dbb.h' --- a/storage/falcon/Dbb.h 2009-02-02 13:00:38 +0000 +++ b/storage/falcon/Dbb.h 2009-02-13 15:53:28 +0000 @@ -29,6 +29,7 @@ #include "PageType.h" #include "SyncObject.h" #include "SparseArray.h" +#include "Mutex.h" #define TRANSACTION_ID(transaction) ((transaction) ? transaction->transactionId : 0) @@ -203,6 +204,7 @@ public: bool utf8; bool noLog; Section *sections[SECTION_HASH_SIZE]; + Mutex sectionsMutex; int debug; int sequence; int odsVersion; -- MySQL Code Commits Mailing List For list archives: http://lists.mysql.com/commits To unsubscribe: http://lists.mysql.com/commits?unsub=commits@bugs.mysql.com
[13 Feb 2009 15:59]
Vladislav Vaintroub
pushed into 6.0-falcon-team. Thanks to Alik to remind me about it, the patch almost got lost.
[2 Mar 2009 14:13]
Bugs System
Pushed into 6.0.11-alpha (revid:alik@sun.com-20090302140208-lfdejjbcyezlhhjt) (version source revid:vvaintroub@mysql.com-20090213155328-oar4mxv61r0k0w39) (merge vers: 6.0.10-alpha) (pib:6)
[15 May 2009 15:56]
MC Brown
A note has been added to the 6.0.11 changelog: mysqld would crash in a concurrent workload with INSERT/CREATE TABLE/DROP TABLE or INSERT/ALTER TABLE combinations on Falcon tables.
