| Bug #37725 | Falcon: assertion in waitForTransaction "waitingFor was not NULL" | ||
|---|---|---|---|
| Submitted: | 29 Jun 2008 11:15 | Modified: | 1 Oct 2008 12:11 |
| Reporter: | Philip Stoev | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: Falcon storage engine | Severity: | S1 (Critical) |
| Version: | 6.0-falcon | OS: | Any |
| Assigned to: | Vladislav Vaintroub | CPU Architecture: | Any |
[29 Jun 2008 11:15]
Philip Stoev
(gdb) print * waitingFor
$4 = {_vptr.Transaction = 0x88a1a10, connection = 0xad813138, database = 0xb7370640, transactionId = 29371, oldestActive = 29287, blockedBy = 0,
curSavePointId = 3, next = 0xb71f8468, prior = 0xb7222240, waitingFor = 0x0, savePoints = 0xb71fef4c, freeSavePoints = 0xb71fef38, localSavePoints = {{
next = 0x0, savepoints = 0xcccccccc, backloggedRecords = 0xcccccccc, records = 0xcccccccc, id = -858993460}, {next = 0xb71fef10,
savepoints = 0xcccccccc, backloggedRecords = 0xcccccccc, records = 0xcccccccc, id = -858993460}, {next = 0xb71fef24, savepoints = 0x0,
backloggedRecords = 0x0, records = 0xb71ff174, id = 3}, {next = 0xb71fef60, savepoints = 0x0, backloggedRecords = 0x0, records = 0xb71ff174, id = 2}, {
next = 0x0, savepoints = 0x0, backloggedRecords = 0x0, records = 0xb71ff174, id = 1}}, deferredIndexes = 0xad81fa98, thread = 0xad813058,
blockingRecord = 0x0, backloggedRecords = 0x0, startTime = 775, deferredIndexCount = 1, statesAllocated = 9, isolationLevel = 8, xidLength = 0,
mySqlThreadId = 9, xid = 0x0, states = 0xb7217cc8, commitTriggers = false, systemTransaction = false, hasUpdates = true, writePending = true,
pendingPageWrites = false, hasLocks = true, syncActive = {<SynchronizationObject> = {_vptr.SynchronizationObject = 0x889f458}, monitorCount = 0,
mutex = {<SynchronizationObject> = {_vptr.SynchronizationObject = 0x88ab7b8}, holder = 0x0, mutex = {__data = {__lock = 0, __count = 0, __owner = 0,
__kind = 0, __nusers = 0, {__spins = 0, __list = {__next = 0x0}}}, __size = '\0' <repeats 23 times>, __align = 0}}, queue = 0xb71abe60,
exclusiveThread = 0xad813058, readers = 0, waiters = 5, lockState = -1, stalls = 6, objectId = 141846, sharedCount = 0, collisionCount = 0,
exclusiveCount = 1, waitCount = 6, queueLength = 15, where = 0x88a1454 "Transaction::waitForTransaction", name = 0xb7200c58 "Transaction::syncActive"},
syncIndexes = {<SynchronizationObject> = {_vptr.SynchronizationObject = 0x889f458}, monitorCount = 0, mutex = {<SynchronizationObject> = {
_vptr.SynchronizationObject = 0x88ab7b8}, holder = 0x0, mutex = {__data = {__lock = 0, __count = 0, __owner = 0, __kind = 0, __nusers = 0, {
__spins = 0, __list = {__next = 0x0}}}, __size = '\0' <repeats 23 times>, __align = 0}}, queue = 0x0, exclusiveThread = 0x0, readers = 0,
waiters = 0, lockState = 0, stalls = 0, objectId = 141847, sharedCount = 0, collisionCount = 0, exclusiveCount = 1, waitCount = 0, queueLength = 0,
where = 0x88a1237 "Transaction::add", name = 0xb71ff1f8 "Transaction::syncIndexes"}, syncObject = {<SynchronizationObject> = {
_vptr.SynchronizationObject = 0x889f458}, monitorCount = 0, mutex = {<SynchronizationObject> = {_vptr.SynchronizationObject = 0x88ab7b8},
holder = 0x0, mutex = {__data = {__lock = 0, __count = 0, __owner = 0, __kind = 0, __nusers = 0, {__spins = 0, __list = {__next = 0x0}}},
__size = '\0' <repeats 23 times>, __align = 0}}, queue = 0x0, exclusiveThread = 0x0, readers = 0, waiters = 0, lockState = 0, stalls = 0,
objectId = 141848, sharedCount = 0, collisionCount = 0, exclusiveCount = 2, waitCount = 0, queueLength = 0, where = 0x88a17aa "Transaction::initialize",
name = 0xb71f8e30 "Transaction::syncObject"}, syncSavepoints = {<SynchronizationObject> = {_vptr.SynchronizationObject = 0x889f458}, monitorCount = 0,
mutex = {<SynchronizationObject> = {_vptr.SynchronizationObject = 0x88ab7b8}, holder = 0x0, mutex = {__data = {__lock = 0, __count = 0, __owner = 0,
__kind = 0, __nusers = 0, {__spins = 0, __list = {__next = 0x0}}}, __size = '\0' <repeats 23 times>, __align = 0}}, queue = 0x0,
exclusiveThread = 0x0, readers = 0, waiters = 0, lockState = 0, stalls = 0, objectId = 141849, sharedCount = 0, collisionCount = 0, exclusiveCount = 0,
waitCount = 0, queueLength = 0, where = 0x0, name = 0xb71ff230 "Transaction::syncSavepoints"}, totalRecordData = 0, totalRecords = 399,
chilledRecords = 0, chilledBytes = 0, thawedRecords = 0, thawedBytes = 0, debugThawedRecords = 0, debugThawedBytes = 0, committedRecords = 0,
deletedRecords = 0, chillPoint = 0xb71ff174, scanIndexCount = 2, numberStates = 8, state = 0, dependencies = 7, useCount = 15, inList = 1,
firstRecord = 0xa9ad0738, lastRecord = 0xa9ad54c8}
[29 Jun 2008 11:15]
Philip Stoev
(gdb) print * transaction
$7 = {_vptr.Transaction = 0x88a1a10, connection = 0xad813138, database = 0xb7370640, transactionId = 29371, oldestActive = 29287, blockedBy = 0,
curSavePointId = 3, next = 0xb71f8468, prior = 0xb7222240, waitingFor = 0x0, savePoints = 0xb71fef4c, freeSavePoints = 0xb71fef38, localSavePoints = {{
next = 0x0, savepoints = 0xcccccccc, backloggedRecords = 0xcccccccc, records = 0xcccccccc, id = -858993460}, {next = 0xb71fef10,
savepoints = 0xcccccccc, backloggedRecords = 0xcccccccc, records = 0xcccccccc, id = -858993460}, {next = 0xb71fef24, savepoints = 0x0,
backloggedRecords = 0x0, records = 0xb71ff174, id = 3}, {next = 0xb71fef60, savepoints = 0x0, backloggedRecords = 0x0, records = 0xb71ff174, id = 2}, {
next = 0x0, savepoints = 0x0, backloggedRecords = 0x0, records = 0xb71ff174, id = 1}}, deferredIndexes = 0xad81fa98, thread = 0xad813058,
blockingRecord = 0x0, backloggedRecords = 0x0, startTime = 775, deferredIndexCount = 1, statesAllocated = 9, isolationLevel = 8, xidLength = 0,
mySqlThreadId = 9, xid = 0x0, states = 0xb7217cc8, commitTriggers = false, systemTransaction = false, hasUpdates = true, writePending = true,
pendingPageWrites = false, hasLocks = true, syncActive = {<SynchronizationObject> = {_vptr.SynchronizationObject = 0x889f458}, monitorCount = 0,
mutex = {<SynchronizationObject> = {_vptr.SynchronizationObject = 0x88ab7b8}, holder = 0x0, mutex = {__data = {__lock = 0, __count = 0, __owner = 0,
__kind = 0, __nusers = 0, {__spins = 0, __list = {__next = 0x0}}}, __size = '\0' <repeats 23 times>, __align = 0}}, queue = 0xb71abe60,
exclusiveThread = 0xad813058, readers = 0, waiters = 5, lockState = -1, stalls = 6, objectId = 141846, sharedCount = 0, collisionCount = 0,
exclusiveCount = 1, waitCount = 6, queueLength = 15, where = 0x88a1454 "Transaction::waitForTransaction", name = 0xb7200c58 "Transaction::syncActive"},
syncIndexes = {<SynchronizationObject> = {_vptr.SynchronizationObject = 0x889f458}, monitorCount = 0, mutex = {<SynchronizationObject> = {
_vptr.SynchronizationObject = 0x88ab7b8}, holder = 0x0, mutex = {__data = {__lock = 0, __count = 0, __owner = 0, __kind = 0, __nusers = 0, {
__spins = 0, __list = {__next = 0x0}}}, __size = '\0' <repeats 23 times>, __align = 0}}, queue = 0x0, exclusiveThread = 0x0, readers = 0,
waiters = 0, lockState = 0, stalls = 0, objectId = 141847, sharedCount = 0, collisionCount = 0, exclusiveCount = 1, waitCount = 0, queueLength = 0,
where = 0x88a1237 "Transaction::add", name = 0xb71ff1f8 "Transaction::syncIndexes"}, syncObject = {<SynchronizationObject> = {
_vptr.SynchronizationObject = 0x889f458}, monitorCount = 0, mutex = {<SynchronizationObject> = {_vptr.SynchronizationObject = 0x88ab7b8},
holder = 0x0, mutex = {__data = {__lock = 0, __count = 0, __owner = 0, __kind = 0, __nusers = 0, {__spins = 0, __list = {__next = 0x0}}},
__size = '\0' <repeats 23 times>, __align = 0}}, queue = 0x0, exclusiveThread = 0x0, readers = 0, waiters = 0, lockState = 0, stalls = 0,
objectId = 141848, sharedCount = 0, collisionCount = 0, exclusiveCount = 2, waitCount = 0, queueLength = 0, where = 0x88a17aa "Transaction::initialize",
name = 0xb71f8e30 "Transaction::syncObject"}, syncSavepoints = {<SynchronizationObject> = {_vptr.SynchronizationObject = 0x889f458}, monitorCount = 0,
mutex = {<SynchronizationObject> = {_vptr.SynchronizationObject = 0x88ab7b8}, holder = 0x0, mutex = {__data = {__lock = 0, __count = 0, __owner = 0,
__kind = 0, __nusers = 0, {__spins = 0, __list = {__next = 0x0}}}, __size = '\0' <repeats 23 times>, __align = 0}}, queue = 0x0,
exclusiveThread = 0x0, readers = 0, waiters = 0, lockState = 0, stalls = 0, objectId = 141849, sharedCount = 0, collisionCount = 0, exclusiveCount = 0,
waitCount = 0, queueLength = 0, where = 0x0, name = 0xb71ff230 "Transaction::syncSavepoints"}, totalRecordData = 0, totalRecords = 399,
chilledRecords = 0, chilledBytes = 0, thawedRecords = 0, thawedBytes = 0, debugThawedRecords = 0, debugThawedBytes = 0, committedRecords = 0,
deletedRecords = 0, chillPoint = 0xb71ff174, scanIndexCount = 2, numberStates = 8, state = 0, dependencies = 7, useCount = 15, inList = 1,
firstRecord = 0xa9ad0738, lastRecord = 0xa9ad54c8}
[29 Jun 2008 15:32]
Philip Stoev
Grammar file for bug 37726
Attachment: bug37725.yy (text/plain), 1.52 KiB.
[29 Jun 2008 15:34]
Philip Stoev
To run the test case, please check out the mysql-test-extra-6.0 tree. Then run: $ cd mysql-test-extra-6.0/mysql-test/gentest $ ./runall.pl --basedir=/path/to/6.0-falcon --engine=Falcon --grammar=/location/of/bug37726.yy The script will start the server and proceed to run random queries against it. Crash should happen within 5 minutes. Please let me know if a simpler test case is required.
[7 Jul 2008 21:57]
Kevin Lewis
Vlad, Will you take a high priority look at this? Philip thinks it is a regression and thus may be a showstopper for 6.0.6.
[8 Jul 2008 10:24]
Philip Stoev
Thread stacks for bug 37725
Attachment: bug37725.threads (text/plain), 37.63 KiB.
[8 Jul 2008 11:14]
Philip Stoev
(gdb) print this->waitingFor
$1 = (volatile Transaction *) 0xb71feee0
(gdb) print * this->waitingFor
$2 = {_vptr.Transaction = 0x88a1a10, connection = 0xad813138,
database = 0xb7370640, transactionId = 29371, oldestActive = 29287,
blockedBy = 0, curSavePointId = 3, next = 0xb71f8468, prior = 0xb7222240,
waitingFor = 0x0, savePoints = 0xb71fef4c, freeSavePoints = 0xb71fef38,
localSavePoints = {{next = 0x0, savepoints = 0xcccccccc,
backloggedRecords = 0xcccccccc, records = 0xcccccccc, id = -858993460}, {
next = 0xb71fef10, savepoints = 0xcccccccc,
backloggedRecords = 0xcccccccc, records = 0xcccccccc, id = -858993460}, {
next = 0xb71fef24, savepoints = 0x0, backloggedRecords = 0x0,
records = 0xb71ff174, id = 3}, {next = 0xb71fef60, savepoints = 0x0,
backloggedRecords = 0x0, records = 0xb71ff174, id = 2}, {next = 0x0,
savepoints = 0x0, backloggedRecords = 0x0, records = 0xb71ff174,
id = 1}}, deferredIndexes = 0xad81fa98, thread = 0xad813058,
blockingRecord = 0x0, backloggedRecords = 0x0, startTime = 775,
deferredIndexCount = 1, statesAllocated = 9, isolationLevel = 8,
xidLength = 0, mySqlThreadId = 9, xid = 0x0, states = 0xb7217cc8,
commitTriggers = false, systemTransaction = false, hasUpdates = true,
writePending = true, pendingPageWrites = false, hasLocks = true,
syncActive = {<SynchronizationObject> = {
_vptr.SynchronizationObject = 0x889f458}, monitorCount = 0,
mutex = {<SynchronizationObject> = {
_vptr.SynchronizationObject = 0x88ab7b8}, holder = 0x0, mutex = {
__data = {__lock = 0, __count = 0, __owner = 0, __kind = 0,
__nusers = 0, {__spins = 0, __list = {__next = 0x0}}},
__size = '\0' <repeats 23 times>, __align = 0}}, queue = 0xb71abe60,
exclusiveThread = 0xad813058, readers = 0, waiters = 5, lockState = -1,
stalls = 6, objectId = 141846, sharedCount = 0, collisionCount = 0,
exclusiveCount = 1, waitCount = 6, queueLength = 15,
where = 0x88a1454 "Transaction::waitForTransaction",
name = 0xb7200c58 "Transaction::syncActive"},
syncIndexes = {<SynchronizationObject> = {
_vptr.SynchronizationObject = 0x889f458}, monitorCount = 0,
mutex = {<SynchronizationObject> = {
_vptr.SynchronizationObject = 0x88ab7b8}, holder = 0x0, mutex = {
__data = {__lock = 0, __count = 0, __owner = 0, __kind = 0,
__nusers = 0, {__spins = 0, __list = {__next = 0x0}}},
__size = '\0' <repeats 23 times>, __align = 0}}, queue = 0x0,
exclusiveThread = 0x0, readers = 0, waiters = 0, lockState = 0,
stalls = 0, objectId = 141847, sharedCount = 0, collisionCount = 0,
exclusiveCount = 1, waitCount = 0, queueLength = 0,
where = 0x88a1237 "Transaction::add",
name = 0xb71ff1f8 "Transaction::syncIndexes"},
syncObject = {<SynchronizationObject> = {
_vptr.SynchronizationObject = 0x889f458}, monitorCount = 0,
mutex = {<SynchronizationObject> = {
_vptr.SynchronizationObject = 0x88ab7b8}, holder = 0x0, mutex = {
__data = {__lock = 0, __count = 0, __owner = 0, __kind = 0,
__nusers = 0, {__spins = 0, __list = {__next = 0x0}}},
__size = '\0' <repeats 23 times>, __align = 0}}, queue = 0x0,
exclusiveThread = 0x0, readers = 0, waiters = 0, lockState = 0,
stalls = 0, objectId = 141848, sharedCount = 0, collisionCount = 0,
exclusiveCount = 2, waitCount = 0, queueLength = 0,
where = 0x88a17aa "Transaction::initialize",
name = 0xb71f8e30 "Transaction::syncObject"},
syncSavepoints = {<SynchronizationObject> = {
_vptr.SynchronizationObject = 0x889f458}, monitorCount = 0,
mutex = {<SynchronizationObject> = {
_vptr.SynchronizationObject = 0x88ab7b8}, holder = 0x0, mutex = {
__data = {__lock = 0, __count = 0, __owner = 0, __kind = 0,
__nusers = 0, {__spins = 0, __list = {__next = 0x0}}},
__size = '\0' <repeats 23 times>, __align = 0}}, queue = 0x0,
exclusiveThread = 0x0, readers = 0, waiters = 0, lockState = 0,
stalls = 0, objectId = 141849, sharedCount = 0, collisionCount = 0,
exclusiveCount = 0, waitCount = 0, queueLength = 0, where = 0x0,
name = 0xb71ff230 "Transaction::syncSavepoints"}, totalRecordData = 0,
totalRecords = 399, chilledRecords = 0, chilledBytes = 0, thawedRecords = 0,
thawedBytes = 0, debugThawedRecords = 0, debugThawedBytes = 0,
committedRecords = 0, deletedRecords = 0, chillPoint = 0xb71ff174,
scanIndexCount = 2, numberStates = 8, state = 0, dependencies = 7,
useCount = 15, inList = 1, firstRecord = 0xa9ad0738, lastRecord = 0xa9ad54c8}
[9 Jul 2008 19:38]
Philip Stoev
Results from testing the patch from http://lists.mysql.com/commits/49256 no patch, no -march=i486 = crash no patch, -march=i486 = no crash patch, -march=i486 = no crash patch, no -march=i486 - does not compile Vlad says: Now my working theory is that without -march=i486, compiler backend would not bother with cmpxchg semantics and that possibly rearranged instructions in such a way that is ZF flag was modified again which would in crash at runtime. I make it the case for Build-Team , I know maria is using exactly the same inline assembly, so it is not only Falcon case. The problem does not seem to appear on gcc4.1, interesting.
[9 Jul 2008 19:56]
Vladislav Vaintroub
Build-team, assigning to you. Basically, what we've found during the test on philips GCC 4.3.0 compiler on 32 bit is that if -march is not set (to i486 or later) compare-exchange inline assembly appears to be broken - the assembly equivalent of __sync_bool_compare_and_swap does not always retuern correct value , using GCC atomic builtins results into link error. So could I make a request to compile with at least -march=i486 on 32 bit linux ? or -march=i586/i686 if you like it better.
[11 Jul 2008 10:23]
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/49547 2731 Vladislav Vaintroub 2008-07-11 Bug#37725 : assertion in transaction::waitForTransaction The patch fixes the problem where Transaction::waitingFor is not reset if LOCK_TIMEOUT exception is thrown by Sync::timedout().
[11 Jul 2008 16:54]
Kevin Lewis
Vlad, Code looks good. Nice catch (pun intended)
[22 Aug 2008 21:21]
Kevin Lewis
This fix is in version 6.0.6
[1 Oct 2008 12:11]
Jon Stephens
Documented in the 6.0.6 changelog as follows:
Binaries built using gcc 4.3 could crash when running large numbers of
DML statements on Falcon tables.
Description: When executing a workload containing randomly-generated DML queries, mysqld crashed as follows: #0 0x00110416 in __kernel_vsyscall () #1 0x00581c78 in pthread_kill () from /lib/libpthread.so.0 #2 0x0844a1c9 in write_core (sig=6) at stacktrace.c:302 #3 0x082a464c in handle_segfault (sig=6) at mysqld.cc:2635 #4 <signal handler called> #5 0x00110416 in __kernel_vsyscall () #6 0x00584fe0 in raise () from /lib/libpthread.so.0 #7 0x0851c754 in Error::debugBreak () at Error.cpp:94 #8 0x0851c7d1 in Error::error (string=0x88a1474 "waitingFor was not NULL") at Error.cpp:71 #9 0x084dddfc in Transaction::waitForTransaction (this=0xb71f8468, transaction=0xb71feee0, transId=0, deadlock=0xad64fa63) at Transaction.cpp:1014 #10 0x084de00f in Transaction::getRelativeState (this=0xb71f8468, transaction=0xb71feee0, transId=29371, flags=1) at Transaction.cpp:872 #11 0x084de0d6 in Transaction::getRelativeState (this=0xb71f8468, record=0xa9ad0738, flags=1) at Transaction.cpp:826 #12 0x084cfdc3 in Table::fetchForUpdate (this=0xb74f9d98, transaction=0xb71f8468, source=0xa9ad0738, usingIndex=true) at Table.cpp:3474 #13 0x084bb191 in StorageDatabase::nextIndexed (this=0xb716f130, storageTable=0xb4fbb2c8, recordBitmap=0xb720e178, recordNumber=1, lockForUpdate=true) at StorageDatabase.cpp:426 #14 0x084c1a27 in StorageTable::nextIndexed (this=0xb4fbb2c8, recordNumber=0, lockForUpdate=true) at StorageTable.cpp:182 #15 0x084b4621 in StorageInterface::index_next (this=0xa1e61c8, buf=0xa1e6390 "ะช") at ha_falcon.cpp:1589 #16 0x084b3036 in StorageInterface::read_range_first (this=0xa1e61c8, start_key=0x0, end_key=0xa1e626c, eq_range_arg=false, sorted=false) at ha_falcon.cpp:1557 #17 0x083cf9cf in handler::multi_range_read_next (this=0xa1e61c8, range_info=0xad64fd20) at handler.cc:4267 #18 0x083aed48 in QUICK_RANGE_SELECT::get_next (this=0xa2b12d8) at opt_range.cc:8518 #19 0x083c995b in rr_quick (info=0xad64fdcc) at records.cc:298 #20 0x083cd1c8 in find_all_keys (param=0xad6500a4, select=0xad500dc0, sort_keys=0xa3c5660, buffpek_pointers=0xad64ff1c, tempfile=0xad64ffe0, indexfile=0x0) at filesort.cc:520 #21 0x083cddeb in filesort (thd=0xa2de3e0, table=0xa36f5d0, sortorder=0xad500ec8, s_length=1, select=0xad500dc0, max_rows=88, sort_positions=true, examined_rows=0xad650368) at filesort.cc:245 #22 0x0835c9a4 in mysql_update (thd=0xa2de3e0, table_list=0xad500730, fields=@0xa2df82c, values=@0xa2dfa58, conds=0xad500b58, order_num=1, order=0xad500cd0, limit=88, handle_duplicates=DUP_ERROR, ignore=false) at sql_update.cc:417 #23 0x082b7bd9 in mysql_execute_command (thd=0xa2de3e0) at sql_parse.cc:2843 #24 0x082be6ab in mysql_parse (thd=0xa2de3e0, inBuf=0xad500618 "UPDATE F AS X SET int_nokey = 76 WHERE X . pk < 17 ORDER BY RAND ( ) LIMIT 88", length=77, found_semicolon=0xad651260) at sql_parse.cc:5799 #25 0x082bf147 in dispatch_command (command=COM_QUERY, thd=0xa2de3e0, packet=0xa31bd69 "UPDATE F AS X SET int_nokey = 76 WHERE X . pk < 17 ORDER BY RAND ( ) LIMIT 88", packet_length=77) at sql_parse.cc:1058 #26 0x082c0408 in do_command (thd=0xa2de3e0) at sql_parse.cc:731 #27 0x082ada2e in handle_one_connection (arg=0xa2de3e0) at sql_connect.cc:1134 #28 0x0057d32f in start_thread () from /lib/libpthread.so.0 #29 0x0049a27e in clone () from /lib/libc.so.6 The crash is in this segment: (gdb) list 1009 return state; 1010 } 1011 1012 1013 if (!COMPARE_EXCHANGE_POINTER(&waitingFor, NULL, transaction)) 1014 FATAL("waitingFor was not NULL"); 1015 1016 volatile Transaction *trans; 1017 for (trans = transaction->waitingFor; trans; trans = trans->waitingFor) 1018 if (trans == this) How to repeat: A test case will be provided if the crash happens again...