Bug #34547 Falcon assertion on shutdown after concurrent CREATE + DROP
Submitted: 14 Feb 2008 15:02 Modified: 20 Sep 2008 11:54
Reporter: Philip Stoev Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server: Falcon storage engine Severity:S2 (Serious)
Version:6.0-falcon-team OS:Any
Assigned to: Christopher Powers CPU Architecture:Any

[14 Feb 2008 15:02] Philip Stoev
Description:
If the following sequence is run in  loop by 5 threads for 120 seconds:

CREATE TEMPORARY TABLE t1 (f1 integer) ENGINE = Falcon;
--let $table_name1 = `SELECT CONCAT('table', CONNECTION_ID(),'1')`
--replace_result $table_name1 <table_name1>
CREATE TABLE $table_name1 ENGINE = Falcon SELECT * FROM t1;
--replace_result $table_name1 <table_name1>
DROP TABLE $table_name1;

,the server will assert like this:

#0  0x00110402 in __kernel_vsyscall ()
#1  0x00bdc617 in pthread_kill () from /lib/libpthread.so.0
#2  0x083f46fb in write_core (sig=4) at stacktrace.c:240
#3  0x0828dc05 in handle_segfault (sig=4) at mysqld.cc:2313
#4  <signal handler called>
#5  0x00110402 in __kernel_vsyscall ()
#6  0x00bdf891 in raise () from /lib/libpthread.so.0
#7  0x084ceaf2 in Error::debugBreak () at Error.cpp:92
#8  0x084ceb49 in Error::error (string=0x8842334 "assertion failed at line %d in file %s\n") at Error.cpp:69
#9  0x084cebb8 in Error::assertionFailed (fileName=0x883901d "SyncObject.cpp", line=125) at Error.cpp:76
#10 0x0849528b in ~SyncObject (this=0xb739adc0) at SyncObject.cpp:125
#11 0x084a3a44 in ~Transaction (this=0xb739ad20) at Transaction.cpp:225
#12 0x084a13b4 in Transaction::release (this=0x4) at Transaction.cpp:987
#13 0x0852e494 in ~TransactionManager (this=0xb71c67a0) at TransactionManager.cpp:67
#14 0x084c30e0 in ~Database (this=0xb73bf628) at Database.cpp:606
#15 0x084b7b13 in Connection::shutdownDatabase (this=0xb71be498) at Connection.cpp:1807
#16 0x0848b53f in StorageDatabase::close (this=0xb71be128) at StorageDatabase.cpp:854
#17 0x0848dea6 in StorageHandler::shutdownHandler (this=0xb73bf028) at StorageHandler.cpp:158
#18 0x0848273f in StorageInterface::panic (hton=0x8b9f030, flag=HA_PANIC_CLOSE) at ha_falcon.cpp:1969
#19 0x08386834 in ha_finalize_handlerton (plugin=0x8b9a0d8) at handler.cc:391
#20 0x08429174 in plugin_deinitialize (plugin=0x8b9a0d8, ref_check=true) at sql_plugin.cc:812
#21 0x0842a926 in reap_plugins () at sql_plugin.cc:900
#22 0x0842aeea in plugin_shutdown () at sql_plugin.cc:1494
#23 0x0828943d in clean_up (print_message=true) at mysqld.cc:1226
#24 0x0828cd20 in unireg_end () at mysqld.cc:1156
#25 0x0828d587 in kill_server (sig_ptr=0x0) at mysqld.cc:1095
#26 0x0828d5cf in kill_server_thread (arg=0xb27a73ac) at mysqld.cc:1116
#27 0x00bd750b in start_thread () from /lib/libpthread.so.0
#28 0x00b18b2e in clone () from /lib/libc.so.6

Upon a restart, recovery works.

How to repeat:
A test case will be attached shortly.
[14 Feb 2008 15:41] Philip Stoev
Test case for bug #34547

Attachment: bug34547.zip (application/x-zip-compressed, text), 485 bytes.

[14 Feb 2008 15:44] Philip Stoev
I have attached a test case. To reproduce, please use:

1. Unzip the archive and place the .txt file  in mysql-test and the .test file in mysql-test/t.

2. Run as follows:

perl ./mysql-test-run.pl --stress --stress-test-file=bug34547_run.txt --stress-test-duration=120 --stress-threads=5 --skip-ndb

3. The test will report a few initial failures because the server has not started yet, please disregard those.

4. The test will run to completion, and after printing "EXIT Stopping All Servers", it will hang. You will see that your mysqld is in status <defunct> and a core has been generated in mysql-test/var/master-data.
[15 Feb 2008 21:24] Sveta Smirnova
Thank you for the report.

Verified as described.
[20 Feb 2008 18:05] Hakan Küçükyılmaz
hakan@lu0011:~/work/mysql/mysql-6.0.4-alpha-linux-x86_64-glibc23/mysql-test$ gdb ../bin/mysqld var/master-data/core.18970
GNU gdb 6.7.1-debian
Copyright (C) 2007 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu"...
Using host libthread_db library "/lib/libthread_db.so.1".
Reading symbols from /lib/libpthread.so.0...done.
Loaded symbols for /lib/libpthread.so.0
Reading symbols from /usr/lib/libstdc++.so.6...done.
Loaded symbols for /usr/lib/libstdc++.so.6
Reading symbols from /lib/libm.so.6...done.
Loaded symbols for /lib/libm.so.6
Reading symbols from /lib/libgcc_s.so.1...done.
Loaded symbols for /lib/libgcc_s.so.1
Reading symbols from /lib/libc.so.6...done.
Loaded symbols for /lib/libc.so.6
Reading symbols from /lib/libdl.so.2...done.
Loaded symbols for /lib/libdl.so.2
Reading symbols from /lib/librt.so.1...done.
Loaded symbols for /lib/librt.so.1
Reading symbols from /lib/libcrypt.so.1...done.
Loaded symbols for /lib/libcrypt.so.1
Reading symbols from /lib/libnsl.so.1...done.
Loaded symbols for /lib/libnsl.so.1
Reading symbols from /lib/ld-linux-x86-64.so.2...done.
Loaded symbols for /lib64/ld-linux-x86-64.so.2
Core was generated by `/home/hakan/work/mysql/mysql-6.0.4-alpha-linux-x86_64-glibc23/bin/mysqld --no-d'.
Program terminated with signal 4, Illegal instruction.
#0  0x00002b5b88abe9c2 in pthread_kill () from /lib/libpthread.so.0
(gdb) info threads
  8 process 18970  0x00002b5b88abdb99 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib/libpthread.so.0
  7 process 18973  0x00002b5b88ac14f9 in do_sigwait () from /lib/libpthread.so.0
  6 process 19011  0x00002b5b88abdb99 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib/libpthread.so.0
  5 process 19012  0x00002b5b88abdb99 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib/libpthread.so.0
  4 process 19013  0x00002b5b88abdb99 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib/libpthread.so.0
  3 process 19014  0x00002b5b88abdb99 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib/libpthread.so.0
  2 process 19015  0x00002b5b88abdb99 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib/libpthread.so.0
* 1 process 30296  0x00002b5b88abe9c2 in pthread_kill () from /lib/libpthread.so.0
(gdb) bt
#0  0x00002b5b88abe9c2 in pthread_kill () from /lib/libpthread.so.0
#1  0x0000000000665203 in handle_segfault ()
#2  <signal handler called>
#3  0x00002b5b88ac169b in raise () from /lib/libpthread.so.0
#4  0x000000000085a2fc in Error::error ()
#5  0x000000000081b331 in SyncObject::~SyncObject ()
#6  0x000000000082a695 in Transaction::~Transaction ()
#7  0x0000000000827ff0 in Transaction::release ()
#8  0x00000000008c236b in TransactionManager::~TransactionManager ()
#9  0x000000000084b02b in Database::~Database ()
#10 0x000000000081086e in StorageDatabase::close ()
#11 0x00000000008131da in StorageHandler::shutdownHandler ()
#12 0x0000000000809321 in StorageInterface::panic ()
#13 0x000000000074a5e4 in ha_finalize_handlerton ()
#14 0x00000000007ccee6 in plugin_deinitialize ()
#15 0x00000000007cfc6a in reap_plugins ()
#16 0x00000000007d03d5 in plugin_shutdown ()
#17 0x0000000000664357 in clean_up ()
#18 0x0000000000668fec in kill_server_thread ()
#19 0x00002b5b88ab93f7 in start_thread () from /lib/libpthread.so.0
#20 0x00002b5b8954997d in clone () from /lib/libc.so.6
#21 0x0000000000000000 in ?? ()
(gdb)
[20 Feb 2008 18:56] Hakan Küçükyılmaz
Verified also with latest mysql-6.0-falcon-team tree. Stacktrace is:

(gdb) bt
#0  0x00002b7c537459c2 in pthread_kill () from /lib/libpthread.so.0
#1  0x0000000000687c27 in handle_segfault (sig=4) at mysqld.cc:2313
#2  <signal handler called>
#3  0x00002b7c5374869b in raise () from /lib/libpthread.so.0
#4  0x000000000087b04a in Error::error (string=<value optimized out>) at Error.cpp:92
#5  0x000000000083cd7c in ~SyncObject (this=0x2aaaaad2fcf8) at SyncObject.cpp:125
#6  0x000000000084c81c in ~Transaction (this=0x2aaaaad2fbb8) at Transaction.cpp:227
#7  0x0000000000849ffe in Transaction::release (this=0x50c6) at Transaction.cpp:992
#8  0x00000000008e0194 in ~TransactionManager (this=0x2aaaaacbaad8) at TransactionManager.cpp:67
#9  0x000000000086bbcf in ~Database (this=0x2aaaaaaaeba0) at Database.cpp:608
#10 0x0000000000832830 in StorageDatabase::close (this=0x2aaaaacaf1b0) at StorageDatabase.cpp:854
#11 0x0000000000834f40 in StorageHandler::shutdownHandler (this=0x2aaaaaaae040)
    at StorageHandler.cpp:158
#12 0x000000000082b07d in StorageInterface::panic (hton=<value optimized out>, flag=20866)
    at ha_falcon.cpp:1969
#13 0x000000000076c06f in ha_finalize_handlerton (plugin=0x1316608) at handler.cc:391
#14 0x00000000007ea278 in plugin_deinitialize (plugin=0x1316608, ref_check=true)
    at sql_plugin.cc:812
#15 0x00000000007ece68 in reap_plugins () at sql_plugin.cc:900
#16 0x00000000007ed596 in plugin_shutdown () at sql_plugin.cc:1494
#17 0x0000000000686dc1 in clean_up (print_message=true) at mysqld.cc:1226
#18 0x000000000068d01d in kill_server_thread (arg=<value optimized out>) at mysqld.cc:1156
#19 0x00002b7c537403f7 in start_thread () from /lib/libpthread.so.0
#20 0x00002b7c54c4597d in clone () from /lib/libc.so.6
#21 0x0000000000000000 in ?? ()
[20 Feb 2008 20:14] Kevin Lewis
DDL synchronization may fix this.
[8 Apr 2008 19:41] Philip Stoev
This bug is still present in 6.0-falcon-team as today. A fresh test case will hopefully follow.
[24 Apr 2008 20:40] Philip Stoev
I can no longer reproduce this bug using the 6.0-falcon-team tree.
[24 Apr 2008 22:16] Christopher Powers
This may have been corrected by the following patch:

You can access the patch from:  http://lists.mysql.com/commits/45964

ChangeSet@stripped, 2008-04-24 13:26:34-04:00, jas@rowvwade. +4 -0
  Changed the way dependencies are handled when committed a transaction 
  without updates.  Rather than trying to resolve unavoidable races
  conditions releasing other transaction's
[19 May 2008 18:23] Philip Stoev
New test case for bug 34547

Attachment: bug34547_2.zip (application/x-zip-compressed, text), 1.29 KiB.

[19 May 2008 18:25] Philip Stoev
This stack trace is now being observed in conjunction with BACKUP DATABASE. I have attached a new test case.

$ perl ./mysql-test-run.pl --stress --stress-init-file=bug34547_2_init.txt --stress-test-file=bug34547_2_run.txt --stress-test-duration=60 --stress-threads=5  --skip-ndb --mysqld=--skip-innodb

Ignore any errors in the output of the test. When the test ends, mysqld will assert.
[20 Sep 2008 11:54] Christopher Powers
Test case succeeds on build from latest mysql-6.0-falcon-team