Bug #43150 Falcon mutex assertion (ret == 0) from Transaction::commitNoUpdates
Submitted: 24 Feb 2009 14:47 Modified: 26 May 2010 17:52
Reporter: Philip Stoev Email Updates:
Status: Unsupported Impact on me:
None 
Category:MySQL Server: Falcon storage engine Severity:S2 (Serious)
Version:6.0-falcon-team OS:Linux
Assigned to: Olav Sandstå CPU Architecture:Any
Tags: F_TRANSACTION

[24 Feb 2009 14:47] Philip Stoev
Description:
Olav asked that this is filed separately from bug 40155. 

When executing a RQG workload, falcon asserted as follows. This only happened once over the course of hundreds of tests:

#7  0x00000000009774c7 in Error::assertionFailed (text=0xe4ec52 "ret == 0",
    fileName=0xe4ec48 "Mutex.cpp", line=92) at Error.cpp:78
#8  0x000000000097bb8f in Mutex::lock (this=0x2aaabc454d70) at Mutex.cpp:92
#9  0x000000000099102a in SyncObject::grantLocks (this=0x2aaabc454d60)
    at SyncObject.cpp:839
#10 0x0000000000991499 in SyncObject::unlock (this=0x2aaabc454d60,
    sync=0x41a6b2f0, type=Exclusive) at SyncObject.cpp:536
#11 0x00000000009907c5 in ~Sync (this=0x41a6b2f0) at Sync.cpp:51
#12 0x00000000009aaaf2 in Transaction::commitNoUpdates (this=0x2aaabc454bf8)
    at Transaction.cpp:353
#13 0x00000000009aac5f in Transaction::commit (this=0x2aaabc454bf8)
    at Transaction.cpp:212
#14 0x00000000009c4446 in Connection::commit (this=0x2aaaaae37378)
    at Connection.cpp:272
#15 0x000000000097ec85 in StorageConnection::commit (this=0x2aaaaae372e0)
    at StorageConnection.cpp:150
#16 0x000000000096f191 in StorageInterface::commit (hton=0x15d5c620,
    thd=0x16aac9b0, all=true) at ha_falcon.cpp:1258
#17 0x000000000081a59b in ha_commit_one_phase (thd=0x16aac9b0, all=true)
    at handler.cc:1223
#18 0x000000000081aaf2 in ha_commit_trans (thd=0x16aac9b0, all=true)
    at handler.cc:1191
#19 0x00000000008ebe34 in trans_commit (thd=0x16aac9b0) at transaction.cc:132
#20 0x00000000006d48a8 in mysql_execute_command (thd=0x16aac9b0)
    at sql_parse.cc:4035
#21 0x00000000006d6af9 in mysql_parse (thd=0x16aac9b0,
    inBuf=0x16ac7e38 "COMMIT", length=6, found_semicolon=0x41a6cf20)
    at sql_parse.cc:5752
#22 0x00000000006d7c8b in dispatch_command (command=COM_QUERY, thd=0x16aac9b0,
    packet=0x16ab7cb1 " COMMIT", packet_length=7) at sql_parse.cc:1009
#23 0x00000000006d911e in do_command (thd=0x16aac9b0) at sql_parse.cc:691
#24 0x00000000006c65da in handle_one_connection (arg=0x16aac9b0)

[Falcon] Error: Mutex::lock: pthread_mutex_lock returned errno 22

22 means "Invalid argument"

How to repeat:
   perl runall.pl  --mem --rows=10000 --threads=32 --mysqld=--falcon-use-supernodes=0    --basedir=/export/home/pb2/test/sb_1-342525-1235419244.13/mysql-6.0.10-alpha-linux-x86_64-test   --mask=524   --queries=10000000   --duration=900   --engine=Falcon   --grammar=conf/transactions-flat.yy   --gendata=conf/transactions.zz   --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
[24 Feb 2009 14:51] Philip Stoev
Mutex from frame 8:

$1 = {<SynchronizationObject> = {_vptr.SynchronizationObject = 0xe4ecd0}, holder = 0x0, mutex = {__data = {__lock = 0, __count = 0, __owner = 0,
      __nusers = 0, __kind = 0, __spins = 0, __list = {__prev = 0x0, __next = 0x0}}, __size = '\0' <repeats 39 times>, __align = 0}}

Sync object from frame 11:

(gdb) print * this
$4 = {_vptr.Sync = 0xe50990, syncObject = 0x2aaabc454d60, state = Exclusive, request = Exclusive, prior = 0x0,
  location = 0xe53390 "Transaction::commitNoUpdates(3)", marked = 0x0}

SyncObject from frame 10:

(gdb) print * this
$6 = {<SynchronizationObject> = {_vptr.SynchronizationObject = 0xe50c90}, monitorCount = 0, mutex = {<SynchronizationObject> = {
      _vptr.SynchronizationObject = 0xe4ecd0}, holder = 0x0, mutex = {__data = {__lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = 0, __spins = 0,
        __list = {__prev = 0x0, __next = 0x0}}, __size = '\0' <repeats 39 times>, __align = 0}}, queue = 0x0, exclusiveThread = 0x0, readers = 0,
  waiters = 0, lockState = 0, stalls = 0, objectId = 661413, sharedCount = 0, collisionCount = 0, exclusiveCount = 2, waitCount = 0, queueLength = 0,
  location = 0xe530f4 "Transaction::initialize(1)", name = 0xe53165 "Transaction::syncObject"}
[7 Mar 2009 8:45] Philip Stoev
This happened 4 out of 82 RQG runs, with the following backtrace:

#2  0x00000000006c1171 in handle_segfault (sig=11) at mysqld.cc:2690
#3  <signal handler called>
#4  0x0000003586e782b0 in strlen () from /lib64/libc.so.6
#5  0x0000003586e46729 in vfprintf () from /lib64/libc.so.6
#6  0x0000003586e47af6 in buffered_vfprintf () from /lib64/libc.so.6
#7  0x0000003586e425dc in vfprintf () from /lib64/libc.so.6
#8  0x0000003586e4cf18 in fprintf () from /lib64/libc.so.6
#9  0x0000000000982b75 in Mutex::lock (this=0x2aaaac5195e0) at Mutex.cpp:90
#10 0x00000000009983e4 in SyncObject::grantLocks (this=0x2aaaac5195d0) at SyncObject.cpp:839
#11 0x0000000000998853 in SyncObject::unlock (this=0x2aaaac5195d0, sync=0x414db8d0, type=Exclusive) at SyncObject.cpp:536
#12 0x0000000000997b51 in ~Sync (this=0x414db8d0) at Sync.cpp:51
#13 0x00000000009b22bc in Transaction::commitNoUpdates (this=0x2aaaac519468) at Transaction.cpp:357
#14 0x00000000009b2429 in Transaction::commit (this=0x2aaaac519468) at Transaction.cpp:212
#15 0x00000000009cbc56 in Connection::commit (this=0x2aaaaae2fcd0) at Connection.cpp:272
#16 0x0000000000985ddf in StorageConnection::commit (this=0x2aaaaae2fc18) at StorageConnection.cpp:150
#17 0x0000000000985716 in StorageConnection::endImplicitTransaction (this=0x2aaaaae2fc18) at StorageConnection.cpp:349
#18 0x0000000000977180 in StorageInterface::external_lock (this=0x2aaab4064a38, thd=0x14d96aa0, lock_type=2) at ha_falcon.cpp:2245
#19 0x0000000000817e63 in handler::ha_external_lock (this=0x2aaab4064a38, thd=0x14d96aa0, lock_type=2) at handler.cc:5449
#20 0x0000000000828a1c in ha_partition::external_lock (this=0x2aaab404d508, thd=0x14d96aa0, lock_type=2) at ha_partition.cc:2686
#21 0x0000000000817e63 in handler::ha_external_lock (this=0x2aaab404d508, thd=0x14d96aa0, lock_type=2) at handler.cc:5449
#22 0x00000000006b6960 in unlock_external (thd=0x14d96aa0, table=0x2aaab800d3b8, count=1) at lock.cc:822
#23 0x00000000006b6ba1 in mysql_unlock_read_tables (thd=0x14d96aa0, sql_lock=0x2aaab800d380) at lock.cc:503
#24 0x000000000075a096 in JOIN::join_free (this=0x2aaab8044bb8) at sql_select.cc:10409
#25 0x000000000075a535 in do_select (join=0x2aaab8044bb8, fields=0x14d98a80, table=0x0, procedure=0x0) at sql_select.cc:15818
#26 0x00000000007770b9 in JOIN::exec (this=0x2aaab8044bb8) at sql_select.cc:2881
#27 0x0000000000771927 in mysql_select (thd=0x14d96aa0, rref_pointer_array=0x14d98b60, tables=0x14db3120, wild_num=0, fields=@0x14d98a80,
    conds=0x2aaab80099b0, og_num=2, order=0x2aaab8009c70, group=0x0, having=0x0, proc_param=0x0, select_options=2147764736, result=0x2aaab8009e80,
    unit=0x14d98510, select_lex=0x14d98978) at sql_select.cc:3062
#28 0x00000000007773d8 in handle_select (thd=0x14d96aa0, lex=0x14d98470, result=0x2aaab8009e80, setup_tables_done_option=0) at sql_select.cc:314
#29 0x00000000006d16e5 in execute_sqlcom_select (thd=0x14d96aa0, all_tables=0x14db3120) at sql_parse.cc:4768
#30 0x00000000006d2753 in mysql_execute_command (thd=0x14d96aa0) at sql_parse.cc:2069
#31 0x00000000006da772 in mysql_parse (thd=0x14d96aa0,
    inBuf=0x14db2198 "SELECT `varchar_1024_utf8` FROM `table10_falcon_key_pk_parts_2_varchar_1024_not_null` WHERE `varchar_1024_latin1_key` IN ( 'mrgimcoktyjscicwpaohurjbqrahryfebllsotktxniqayyvcwqdtokispdudyarpwbhsfljdukp"..., length=1579, found_semicolon=0x414ddf20) at sql_parse.cc:5763
#32 0x00000000006db903 in dispatch_command (command=COM_QUERY, thd=0x14d96aa0, packet=0x14da1461 "", packet_length=1579) at sql_parse.cc:1009
#33 0x00000000006dcd96 in do_command (thd=0x14d96aa0) at sql_parse.cc:691
#34 0x00000000006ca19a in handle_one_connection (arg=0x14d96aa0) at sql_connect.cc:1146
#35 0x0000003587a062f7 in start_thread () from /lib64/libpthread.so.0
#36 0x0000003586ed1b6d in clone () from /lib64/libc.so.6

(gdb) print description
$14 = 0xe662d0 "SyncObject::mutex"
(gdb) print ret
$15 = 22