| Bug #22165 | ALTER crash if two interleaving transactions | ||
|---|---|---|---|
| Submitted: | 9 Sep 2006 9:40 | Modified: | 30 Sep 2008 17:54 |
| Reporter: | Georg Richter | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: Falcon storage engine | Severity: | S1 (Critical) |
| Version: | 6.0, 6.0-falcon tree | OS: | Linux (Linux) |
| Assigned to: | Vladislav Vaintroub | CPU Architecture: | Any |
[7 Oct 2006 21:43]
Hakan Küçükyılmaz
Test case is falcon_bug_195.test. There was a change in the event handling. I updated the test case. Now I get this error: falcon_bug_195 [ fail ] Errors are (from /home/hakan/work/mysql/mysql-5.1-falcon/mysql-test/var/log/mysqltest-time) : mysqltest: Result length mismatch (the last lines may be the most important ones) Below are the diffs between actual and expected results: ------------------------------------------------------- *** r/falcon_bug_195.result 2006-10-07 23:36:43.000000000 +0300 --- r/falcon_bug_195.reject 2006-10-07 23:39:03.000000000 +0300 *************** *** 32,34 **** --- 32,36 ---- DROP event db6.e2// DROP PROCEDURE db6.pf4// DROP DATABASE db6// + Warnings: + Note 1051 Unknown table '#sql-46cb_35' ------------------------------------------------------- Regards, Hakan
[16 Nov 2006 23:44]
Hakan Küçükyılmaz
Still failing with the same error message. I used Linux 32-bit, change set 1.2363, 2006-11-15. TEST RESULT TIME (ms) ------------------------------------------------------- falcon_bug_195 [ fail ] ERROR: Mantis bug #195 2006-08-24 hakank (Get pushbuild green) Below are the diffs between actual and expected results: ------------------------------------------------------- *** r/falcon_bug_195.result 2006-10-08 01:21:00.000000000 +0300 --- r/falcon_bug_195.reject 2006-11-17 02:02:56.000000000 +0300 *************** *** 32,34 **** --- 32,36 ---- DROP EVENT db1.e2// DROP PROCEDURE db1.p1// DROP DATABASE db1// + Warnings: + Note 1051 Unknown table '#sql-4818_2b' ------------------------------------------------------- Please follow the instructions outlined at http://www.mysql.com/doc/en/Reporting_mysqltest_bugs.html to find the reason to this problem and how to report this. Regards, Hakan
[14 Apr 2007 13:38]
Hakan Küçükyılmaz
Renamed test case to falcon_bug_22165.test.
[30 Apr 2007 18:22]
Kevin Lewis
This crash does not occur anymore with the current code. However, there seems to be a disconnect between the test file and the result. Also, the test script takes a while to kill the scheduler on Linux and is unable to kill it on Windows. Also, the test outputs an unex[ected warning; + Warnings: + Note 1051 Unknown table '#sql-117d_6b' Hakan, can you clean up this test and determine if anything is really wrong with it anymore?
[1 May 2007 9:27]
Hakan Küçükyılmaz
Running the test case with InnoDB reveals no such problems. TEST RESULT TIME (ms) ------------------------------------------------------- falcon_bug_22165 [ pass ] 60142 ------------------------------------------------------- Stopping All Servers All 1 tests were successful. The servers where restarted 1 times Spent 60.142 seconds actually executing testcases Whereas running the test case with Falcon gives: TEST RESULT TIME (ms) ------------------------------------------------------- falcon_bug_22165 [ fail ] ERROR: Bug#22165 2006-08-24 hakank (Get pushbuild green) Below are the diffs between actual and expected results: ------------------------------------------------------- *** r/falcon_bug_22165.result 2007-05-01 12:25:24.000000000 +0300 --- r/falcon_bug_22165.reject 2007-05-01 12:26:39.000000000 +0300 *************** *** 32,34 **** --- 32,36 ---- DROP EVENT db1.e2// DROP PROCEDURE db1.p1// DROP DATABASE db1// + Warnings: + Note 1051 Unknown table '#sql-1457_7a' ------------------------------------------------------- Best regards, Hakan
[1 May 2007 9:29]
Hakan Küçükyılmaz
Crash does not happen anymore.
[3 May 2007 10:52]
MC Brown
A note has been added to the 6.0.0 changelog.
[25 Apr 2008 8:10]
Vladislav Vaintroub
Crash still appears The test case crashes on about every linux in pushbuild. On Windows, I was able to reproduce it once, while increasing number of threads (i.e events in the test case) to 35. Crash happens during implicit COMMIT during the in ALTER TABLE. From crash report: [thd->query at 000000000C670F30=ALTER TABLE t1 MODIFY COLUMN c timestamp] The valgrind message before the crash, 2 days ago: pb-valgrind: ==3550== Thread 25: ==3550== Invalid read of size 8 ==3550== at 0x8D54CA: Table::updateRecord(RecordVersion*) (LinkedList.h:81) ==3550== by 0x8E5122: Transaction::commit() (Transaction.cpp:281) ==3550== by 0x8FC220: Connection::commit() (Connection.cpp:269) ==3550== by 0x8C68BA: StorageConnection::commit() (StorageConnection.cpp:146) ==3550== by 0x8C9DCD: StorageHandler::commit(THD*) (StorageHandler.cpp:264) ==3550== by 0x8C15C4: StorageInterface::commit(handlerton*, THD*, bool) (ha_falcon.cpp:1143) ==3550== by 0x7AC9D9: ha_commit_one_phase(THD*, bool) (handler.cc:1168) ==3550== by 0x7ACE1F: ha_commit_trans(THD*, bool) (handler.cc:1137) ==3550== by 0x6A1CC9: end_trans(THD*, enum_mysql_completiontype) (sql_parse.cc:579) ==3550== by 0x6A53FF: mysql_execute_command(THD*) (sql_parse.cc:3863) ==3550== by 0x8313BB: sp_instr_stmt::exec_core(THD*, unsigned*) (sp_head.cc:2861) ==3550== by 0x834779: sp_lex_keeper::reset_lex_and_exec_core(THD*, unsigned*, bool, sp_instr*) (sp_head.cc:2691) ==3550== by 0x837458: sp_instr_stmt::execute(THD*, unsigned*) (sp_head.cc:2804) ==3550== by 0x835A50: sp_head::execute(THD*) (sp_head.cc:1215) ==3550== by 0x8386F7: sp_head::execute_procedure(THD*, List<Item>*) (sp_head.cc:1939) ==3550== by 0x6A378A: mysql_execute_command(THD*) (sql_parse.cc:4150) Windows callstack (today): 0000000140444BD6 mysqld.exe!Transaction::commit()[transaction.cpp:297] 000000014042A0F3 mysqld.exe!Connection::commit()[connection.cpp:270] 0000000140400F2F mysqld.exe!StorageConnection::commit()[storageconnection.cpp:149] 00000001403F4B2E mysqld.exe!StorageInterface::commit()[ha_falcon.cpp:1153] 000000014002C291 mysqld.exe!ha_commit_one_phase()[handler.cc:1168] 000000014003092F mysqld.exe!ha_commit_trans()[handler.cc:1137] 000000014016B5C4 mysqld.exe!end_active_trans()[sql_parse.cc:132] 0000000140173B2B mysqld.exe!mysql_execute_command()[sql_parse.cc:2591] 0000000140110538 mysqld.exe!sp_instr_stmt::exec_core()[sp_head.cc:2862] 00000001401131E2 mysqld.exe!sp_lex_keeper::reset_lex_and_exec_core()[sp_head.cc:2691] 0000000140114C96 mysqld.exe!sp_instr_stmt::execute()[sp_head.cc:2806] 0000000140115356 mysqld.exe!sp_head::execute()[sp_head.cc:1215] 00000001401165DB mysqld.exe!sp_head::execute_procedure()[sp_head.cc:1939] 000000014017771E mysqld.exe!mysql_execute_command()[sql_parse.cc:4150] 0000000140110538 mysqld.exe!sp_instr_stmt::exec_core()[sp_head.cc:2862] 00000001401131E2 mysqld.exe!sp_lex_keeper::reset_lex_and_exec_core()[sp_head.cc:2691] 0000000140114C96 mysqld.exe!sp_instr_stmt::execute()[sp_head.cc:2806] 0000000140115356 mysqld.exe!sp_head::execute()[sp_head.cc:1215] 00000001401165DB mysqld.exe!sp_head::execute_procedure()[sp_head.cc:1939] 0000000140209D65 mysqld.exe!Event_job_data::execute()[event_data_objects.cc:1987] 0000000140206989 mysqld.exe!Event_worker_thread::run()[event_scheduler.cc:312] 0000000140206AF5 mysqld.exe!event_worker_thread()[event_scheduler.cc:265] 000000014029DE25 mysqld.exe!pthread_start()[my_winthread.c:87] 00000001404DF5D7 mysqld.exe!_callthreadstart()[thread.c:295] 00000001404DF6A5 mysqld.exe!_threadstart()[thread.c:275] 0000000077A2495D kernel32.dll!BaseThreadInitThunk() 0000000077C28791 ntdll.dll!RtlUserThreadStart()
[25 Apr 2008 9:19]
Vladislav Vaintroub
Here is the source snippet of the crash location on Windows, Transaction.cpp , line 295 ff for (RecordVersion *record = firstRecord; record; record = record->nextInTrans) if (!record->getPriorVersion()) ++record->format->table->cardinality; /*<--CRASH HERE */ else if (record->state == recDeleted && record->format->table->cardinality > 0) --record->format->table->cardinality;
[25 Apr 2008 15:56]
MySQL Verification Team
I could not repeat the crash running the >1h on Windows XP with the latest source server.
[25 Apr 2008 17:15]
Hakan Küçükyılmaz
Running falcon_bug_22165 several times in a row eventually gave me this stacktrace:
./mysql-test-run.pl --force --mem --suite=falcon_team falcon_bug_22165 falcon_bug_22165 falcon_bug_22165, ..., falcon_bug_22165
Program terminated with signal 11, Segmentation fault.
#0 0x00002b1ae67b76b2 in pthread_kill () from /lib/libpthread.so.0
(gdb) bt
#0 0x00002b1ae67b76b2 in pthread_kill () from /lib/libpthread.so.0
#1 0x00000000007c670c in write_core (sig=11) at stacktrace.c:305
#2 0x0000000000662875 in handle_segfault (sig=11) at mysqld.cc:2624
#3 <signal handler called>
#4 Table::updateRecord (this=0xeeeeeeeeeeeeeeee, record=0x7b403a0) at Table.cpp:446
#5 0x0000000000842c0c in Transaction::commit (this=0x20cf9e0) at Transaction.cpp:282
#6 0x000000000085737d in Connection::commit (this=0x2aaab06073f0) at Connection.cpp:269
#7 0x0000000000827309 in StorageConnection::commit (this=0x2aaab0607358)
at StorageConnection.cpp:146
#8 0x00000000008217a9 in StorageInterface::commit (hton=<value optimized out>,
thd=0x2aaab060b938, all=true) at ha_falcon.cpp:1141
#9 0x000000000075efb6 in ha_commit_one_phase (thd=0x2aaab060b938, all=true) at handler.cc:1168
#10 0x000000000075f45b in ha_commit_trans (thd=0x2aaab060b938, all=<value optimized out>)
at handler.cc:1137
#11 0x000000000066a2a7 in end_trans (thd=0x2aaab060b938, completion=COMMIT) at sql_parse.cc:579
#12 0x0000000000671598 in mysql_execute_command (thd=0x2aaab060b938) at sql_parse.cc:3863
#13 0x00000000007d8774 in sp_instr_stmt::exec_core (this=0x1316578, thd=0x7b403a0,
nextp=0x2b1ae67bc508) at sp_head.cc:2861
#14 0x00000000007d897c in sp_lex_keeper::reset_lex_and_exec_core (this=0x13165b8,
thd=0x2aaab060b938, nextp=0x459cfad4, open_tables=false, instr=0x1316578) at sp_head.cc:2691
#15 0x00000000007dfb8e in sp_instr_stmt::execute (this=0x1316578, thd=0x2aaab060b938,
nextp=0x459cfad4) at sp_head.cc:2804
#16 0x00000000007dccd5 in sp_head::execute (this=0x1374ef8, thd=0x2aaab060b938) at sp_head.cc:1215
#17 0x00000000007dd682 in sp_head::execute_procedure (this=0x1374ef8, thd=0x2aaab060b938,
args=0x136de18) at sp_head.cc:1939
[28 Apr 2008 20:37]
Kevin Lewis
May be related to Bug#28048
[4 Jun 2008 13:11]
Vladislav Vaintroub
Table::updateRecord (this=0xeeeeeeeeeeeeeeee) in the callstack suggests that table has been freed before use (0xee is pattern for free memory)
[21 Jul 2008 14:15]
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/50118 2751 Vladislav Vaintroub 2008-07-21 Accoding to Kevin, Bug#22165 could have been fixed with his fix to 36438. This change reactivates the test case
[21 Jul 2008 14:17]
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/50119 2751 Vladislav Vaintroub 2008-07-21 Accoding to Kevin, Bug#22165 could have been fixed with his fix to 36438. This change reactivates the test case
[22 Jul 2008 13:20]
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/50190 2752 Vladislav Vaintroub 2008-07-22 The problem was not solved with 36438, disable test case again
[11 Aug 2008 13: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/51311 2772 Vladislav Vaintroub 2008-08-11 Bug#22165 - crash while doing ALTER in parallel with another transactions Eliminated races. Race condition 1. ALTER/DROP/TRUNCATE have to ensure that table has no committed records that are not yet "write complete". Otherwise crash is possible if table is deleted, but then accessed during Transaction::writeComplete() in Record::poke() It is now solved, Storage::external_lock will wait for all transaction on the table to become write complete, if there is no uncommited records. Race condition 2. In Transaction::commit(), Transaction state is set to Committed to early while the transaction is still in the active list. This can produce incorrect results in Transaction::hasUncommitedRecords, DROP is not blocked. When later Transaction::commit() traverses the record list, it can crash accessing freed memory in Table::updateRecord(). This is fixed and transaction state is changed during the transition from active list to committed list.
[14 Aug 2008 7:33]
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/51602 2684 He Zhenxing 2008-08-14 [merge] Merge 6.0 -> 6.0-rpl-testfixes
[14 Aug 2008 7:36]
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/51603 2684 He Zhenxing 2008-08-14 [merge] Merge 6.0 -> 6.0-rpl-testfixes
[25 Aug 2008 15:36]
Kevin Lewis
This fix is in version 6.0.7
[28 Aug 2008 20:14]
Bugs System
Pushed into 6.0.7-alpha (revid:cbell@mysql.com-20080822132131-uveo6wiuecy6m2b8) (version source revid:cbell@mysql.com-20080822132131-uveo6wiuecy6m2b8) (pib:3)
[9 Sep 2008 13:34]
Kevin Lewis
On 9Sep2008 Vlad pushed this patch http://lists.mysql.com/commits/53551. It is a follow-on change to this bug as well as Bug#38947. This patch moves the assignment of the transaction state and the signalling of waiting threads until the end of the rollback, as he did earlier for Transaction::commit. Here is the reasoning behind this change; Vlad wrote this comment above; Race condition 2. In Transaction::commit(), Transaction state is set to Committed too early while the transaction is still in the active list. This can produce incorrect results in Transaction::hasUncommitedRecords, DROP is not blocked. When later Transaction::commit() traverses the record list, it can crash accessing freed memory in Table::updateRecord(). So if a transaction is still on the active list and we say it is committed, and signal all waiters, then waiting threads get started before it gets moved to the committed list. TransactionManager::waitForWriteComplete(Table* table) only looks into the committed list, not the activeTransaction list. So if signaling early causes the DDL thread to go early, then the table might disappear while the commit is still happening. Why would the DDL thread be waiting on a transaction? It calls TransactionManager::hasUncommittedRecords via StorageTable::alterCheck. This function would wait on activeTransactions, not the transaction itself. But if there is another thread in the engine waiting on that transaction, the DDL would be back in the server waiting for that thread to finish and come out. (The server does not serialize DDL with commit statements since the server does not know what tables are involved.) So here is the scenario. A DDL is waiting in the server for a lock on the table. A table operation is waiting in Falcon for a Transaction to commit or rollback. The commit finally comes in, it signals the waiting thread early, before moving itself from the active to committed lists. The waiting thread finishes with that table and the DDL comes in and calls Transaction::hasRecords. It looks for the transaction in the active list, finds it but it is committed (isActive() == false) and hasRecords() also returns false. So the DDL then calls waitForTransComplete and does not find the transaction in the committed list either, so it does not wait. The table is dropped. Later, as part of the continuing commit, maybe during releaseDependencies, the table->format is accessed. Bang. So why should the rollback also signal othre transactions when it is completely finished? In the same manner as above, the drop table could get started and finished before the rollback has completed. There might be problems in release dependencies or elsewhere. It is better practice be completely finished transitioning an active transaction before signalling that we are done.
[13 Sep 2008 20:55]
Bugs System
Pushed into 6.0.7-alpha (revid:vvaintroub@mysql.com-20080811132253-4go0vfgcn59z91qu) (version source revid:hakan@mysql.com-20080725175322-8wgujj5xuzrjz3ke) (pib:3)
[30 Sep 2008 17:54]
Jon Stephens
Documented as follows in the 6.0.7 changelog:
Using ALTER TABLE with interleaving transactions
could cause mysqld to crash.
This fix supersedes an earlier one for this issue that appeared in MySQL
6.0.0.
Description: I create a short procedure which inserts and updates, on a Falcon table. (On an InnoDB table, there's no problem.) If errors occur, I have a statement which alters the table. (If there's no ALTER, there's no problem.) I call this procedure from two events, so there are interleaving transactions. (MySQL 5.1's events make some concurrency tests much easier to write.) Within 5 minutes of starting the event scheduler, I see a crash. Bug still exists in change set 1.2279 Backtrace is: Program received signal SIGSEGV, Segmentation fault. [Switching to Thread 1674820528 (LWP 32012)] 0x085e46c1 in Table::touched (this=0x8cee5e0) at Table.cpp:1447 1447 ageGroup = database->currentAgeGroup; 0 0x085e46c1 in Table::touched (this=0x8cee5e0) at Table.cpp:1447 1 0x08638073 in RecordVersion::commit (this=0x8d9dc58) at RecordVersion.cpp:95 0000002 0x085eac4d in Transaction::commitRecords (this=0x8d14fd0) at Transaction.cpp:289 0000003 0x085eaf74 in Transaction::commit (this=0x8db6648) at Transaction.cpp:154 0000004 0x085fbeb2 in Connection::commit (this=0x8db2da0) at Connection.cpp:267 0000005 0x085d6eb7 in StorageConnection::commit (this=0x8db4960) at StorageConnection.cpp:247 0000006 0x085cd843 in NfsStorageTable::commit (thd=0x8d671f8, all=false) at ha_falcon.cpp:602 0000007 0x0832d174 in ha_commit_one_phase (thd=0x8d671f8, all=false) at handler.cc:718 0000008 0x0832d7e3 in ha_commit_trans (thd=0x8d671f8, all=false) at handler.cc:688 0000009 0x0832da6a in ha_autocommit_or_rollback (thd=0x8d671f8, error=0) at handler.cc:827 0000010 0x082d15ed in mysql_update (thd=0x8d671f8, table_list=0x8d84e38, fields=@0x8d96cd4, values=@0x8d96ea8, conds=0x8d852b8, order_num=0, order=0x0, limit=18446744073709551613, handle_duplicates=DUP_ERROR, ignore=false) at sql_update.cc:668 0000011 0x0825c998 in mysql_execute_command (thd=0x8d671f8) at sql_parse.cc:3267 0000012 0x083cdcdf in sp_instr_stmt::exec_core (this=0x8d853a8, thd=0x8d671f8, nextp=0x63d3a5ec) at sp_head.cc:2356 0000013 0x083cdaeb in sp_lex_keeper::reset_lex_and_exec_core (this=0x8d853d0, thd=0x8d671f8, nextp=0x63d3a5ec, open_tables=false, instr=0x8d853a8) at sp_head.cc:2230 0000014 0x083d0809 in sp_instr_stmt::execute (this=0x8d853a8, thd=0x8d671f8, nextp=0x63d3a5ec) at sp_head.cc:2307 0000015 0x083cab32 in sp_head::execute (this=0x8d83a60, thd=0x8d671f8) at sp_head.cc:1084 0000016 0x083cbcf9 in sp_head::execute_procedure (this=0x8d83a60, thd=0x8d671f8, args=0x8d7a010) at sp_head.cc:1559 0000017 0x08260cbf in mysql_execute_command (thd=0x8d671f8) at sql_parse.cc:4600 0000018 0x083cdcdf in sp_instr_stmt::exec_core (this=0x8d73c40, thd=0x8d671f8, nextp=0x63d3b1cc) at sp_head.cc:2356 0000019 0x083cdaeb in sp_lex_keeper::reset_lex_and_exec_core (this=0x8d73c68, thd=0x8d671f8, nextp=0x63d3b1cc, open_tables=false, instr=0x8d73c40) at sp_head.cc:2230 0000020 0x083d0809 in sp_instr_stmt::execute (this=0x8d73c40, thd=0x8d671f8, nextp=0x63d3b1cc) at sp_head.cc:2307 0000021 0x083cab32 in sp_head::execute (this=0x8d73908, thd=0x8d671f8) at sp_head.cc:1084 0000022 0x083cbcf9 in sp_head::execute_procedure (this=0x8d73908, thd=0x8d671f8, args=0x63d3b364) at sp_head.cc:1559 0000023 0x083e903e in Event_timed::execute (this=0x8d289b8, thd=0x8d671f8, mem_root=0x8d67218) at event_timed.cc:1412 0000024 0x083dd832 in event_worker_thread (arg=0x4171e320) at event_scheduler.cc:567 0000025 0x40282297 in start_thread () from /lib/tls/libpthread.so.0 0000026 0x4021737e in clone () from /lib/tls/libc.so.6 0000027 0x63d3bbb0 in ?? () How to repeat: How to repeat: delimiter // use test// create database db6// use db6// create procedure pf4 () begin declare v int default 0; declare continue handler for sqlexception begin declare continue handler for sqlexception begin end; alter table t modify column s3 timestamp; end; while v < 10 do start transaction; set transaction isolation level read committed; insert into t (s1,s2) values (v,'a'); update t set s3 = current_timestamp where s1 = v; commit; set v = v + 1; end while; end// create table t (s1 bigint, s2 varchar(1000), s3 timestamp) engine=falcon// create event e1 on schedule every 1 second do call db6.pf4()// create event e2 on schedule every 1 second do call db6.pf4()// set global event_scheduler = 1// Suggested fix: mantis bug #195