| Bug #52580 | Crash in ha_innobase::open on executing INSERT with concurrent ALTER TABLE | ||
|---|---|---|---|
| Submitted: | 4 Apr 2010 1:17 | Modified: | 15 Jun 2010 14:57 |
| Reporter: | Elena Stepanova | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: InnoDB storage engine | Severity: | S1 (Critical) |
| Version: | 5.5.4-m3 | OS: | Any |
| Assigned to: | Jimmy Yang | CPU Architecture: | Any |
| Tags: | regression | ||
[4 Apr 2010 1:22]
Elena Stepanova
mysql-stress-test-based test
Attachment: bug52580_stress_test.tar.gz (application/x-gzip, text), 1.83 KiB.
[6 Apr 2010 11:34]
Konstantin Osipov
I can't repeat the bug locally on either mysql-trunk-runtime-exp or mysql-trunk-iplus-test. The backtrace analysis suggests that bug is not in the server:
the crashed connection has a valid metadata lock (as expected), and the
ALTER statement is rightfully blocked on that metadata lock.
TABLE_SHARE of the crashed connection is valid:
(gdb) p thd->mdl_context.m_tickets
$3 = {<I_P_List_null_counter> = {<No data fields>}, first = 0x80f08a0}
(gdb) p thd->mdl_context.m_tickets.first
$4 = (MDL_ticket *) 0x80f08a0
(gdb) p *thd->mdl_context.m_tickets.first
$5 = {next_in_context = 0x0, prev_in_context = 0x80f7dc8,
next_in_lock = 0x8111290, prev_in_lock = 0x80f2f50,
m_type = MDL_SHARED_WRITE, m_ctx = 0x80f7dc8, m_lock = 0x80f2d70}
(gdb) p *thd->mdl_context.m_tickets.first->m_lock
$6 = {_vptr.MDL_lock = 0xa771f0, key = {m_length = 10, m_db_name_length = 4,
m_ptr = "\001test\000tb0", '\0' <repeats 131 times>, "\002\000 '\177\000\000\001", '\0' <repeats 120 times>, "\020\000\000\000\000\000\000\000TCP/IP (34)", '\0' <repeats 45 times>, "ðò\220\000\000\000\000\000Ðü\220\000\000\000\000\000`ý\220\000\000\000\000\000Pý\220\000\000\000\000\000àü\220\000\000\000\000\000Ð÷\220\000\000\000\000\000Ðø\220\000\000\000"}, cached_object = 0x811d570,
cached_object_release_hook = 0x62ef50 <table_share_release_hook(void*)>,
m_rwlock = {m_prlock = {__rw_lock = {__status = 0, __spinlock = 1},
__rw_readers = 0, __rw_writer = 0x0, __rw_read_waiting = 0x90f890,
__rw_write_waiting = 0x90f990, __rw_kind = 0, __rw_pshared = 0},
m_psi = 0x2aaaac22a658}, m_granted = {
m_list = {<I_P_List_null_counter> = {<No data fields>},
first = 0x80f08a0}, m_bitmap = 16 '\020'}, m_waiting = {
m_list = {<I_P_List_null_counter> = {<No data fields>},
first = 0x80e3160}, m_bitmap = 32 ' '}, m_ref_usage = 71,
m_ref_release = 71, m_is_destroyed = false}
(gdb) p *thd->mdl_context.m_tickets.first->m_lock->m_cached_object
There is no member or method named m_cached_object.
(gdb) p *thd->mdl_context.m_tickets.first->m_lock->cached_object
Attempt to dereference a generic pointer.
(gdb) p thd->mdl_context.m_tickets.first->m_lock->cached_object
$7 = (void *) 0x811d570
(gdb) p (TABLE_SHARE*)(thd->mdl_context.m_tickets.first->m_lock->cached_object)
$8 = (TABLE_SHARE *) 0x811d570
(gdb) p *(TABLE_SHARE*)(thd->mdl_context.m_tickets.first->m_lock->cached_object)
$9 = {table_category = TABLE_CATEGORY_USER, name_hash = {key_offset = 0,
key_length = 0, blength = 0, records = 0, flags = 0, array = {
buffer = 0x0, elements = 0, max_element = 0, alloc_increment = 0,
size_of_element = 0}, get_key = 0, free = 0, charset = 0x0}, mem_root = {
free = 0x80f7230, used = 0x811d560, pre_alloc = 0x0, min_malloc = 32,
block_size = 992, block_num = 7, first_block_usage = 1,
error_handler = 0x5843f0 <sql_alloc_error_handler>}, keynames = {
count = 1, name = 0x0, type_names = 0x811d918, type_lengths = 0x0},
fieldnames = {count = 1, name = 0x0, type_names = 0x811d908,
type_lengths = 0x0}, intervals = 0x0, LOCK_ha_data = {m_mutex = {mutex = {
__m_reserved = 0, __m_count = 0, __m_owner = 0x0, __m_kind = 3,
__m_lock = {__status = 0, __spinlock = 0}}, spins = 8, rng_state = 1},
m_psi = 0x2aaaac214150}, next = 0x0, prev = 0x0,
used_tables = {<I_P_List_null_counter> = {<No data fields>},
first = 0x805c370},
free_tables = {<I_P_List_null_counter> = {<No data fields>}, first = 0x0},
field = 0x811d8f8, found_next_number_field = 0x0, timestamp_field = 0x0,
key_info = 0x80f7240, blob_field = 0x0,
default_values = 0x80f72d0 "ÿ", ' ' <repeats 199 times>..., comment = {
str = 0x811d8f0 "", length = 0}, table_charset = 0xed59c0, all_set = {
bitmap = 0x80f75d8, n_bits = 1, last_word_mask = 4294967294,
last_word_ptr = 0x80f75d8, mutex = 0x0}, table_cache_key = {
str = 0x811d8c0 "test", length = 9}, db = {str = 0x811d8c0 "test",
length = 4}, table_name = {str = 0x811d8c5 "tb0", length = 3}, path = {
str = 0x811d8d0 "./test/tb0", length = 10}, normalized_path = {
str = 0x811d8d0 "./test/tb0", length = 10}, connect_string = {
str = 0x811d8e8 "", length = 0}, keys_in_use = {map = 1},
keys_for_keyread = {map = 1}, min_rows = 0, max_rows = 0,
avg_row_length = 0, raid_chunksize = 0, mysql_version = 50504,
timestamp_offset = 0, reclength = 256, db_plugin = 0x7b5f1e0,
row_type = ROW_TYPE_DEFAULT, tmp_table = NO_TMP_TABLE,
unused1 = HA_CHOICE_UNDEF, unused2 = HA_CHOICE_UNDEF, version = 1,
ref_count = 3, open_count = 0, blob_ptr_size = 8, key_block_size = 0,
null_bytes = 1, last_null_bit_pos = 2, fields = 1, rec_buff_length = 264,
keys = 1, key_parts = 1, max_key_length = 257, max_unique_length = 0,
total_key_length = 256, uniques = 0, null_fields = 1, blob_fields = 0,
timestamp_field_offset = 0, varchar_fields = 0, db_create_options = 8,
db_options_in_use = 8, db_record_offset = 1, raid_type = 0, raid_chunks = 0,
rowid_field_offset = 0, primary_key = 64, next_number_index = 0,
next_number_key_offset = 0, next_number_keypart = 0, error = 0,
open_errno = 0, errarg = 0, column_bitmap_size = 4, frm_version = 10 '\n',
null_field_first = true, system = false, crypted = false,
db_low_byte_first = true, crashed = false, is_view = false,
table_map_id = 204, table_map_version = 18446744073709551615,
cached_row_logging_check = 1, auto_partitioned = false,
partition_info = 0x0, partition_info_len = 0,
partition_info_buffer_size = 0, part_state = 0x0, part_state_len = 0,
---Type <return> to continue, or q <return> to quit---
default_part_db_type = 0x0, table_field_def_cache = 0x0, ha_data = 0x0,
ha_data_destroy = 0, m_psi = 0x0}
[6 Apr 2010 11:34]
Konstantin Osipov
Other active threads:
(gdb) thread 2
[Switching to thread 2 (process 9066)]#0 0x0000003ba880d3b7 in fsync ()
from /lib64/libpthread.so.0
(gdb) bt
#0 0x0000003ba880d3b7 in fsync () from /lib64/libpthread.so.0
#1 0x00000000007e8c45 in os_file_flush_func (file=9) at os/os0file.c:2041
#2 0x000000000089c73a in fil_flush (space_id=<value optimized out>)
at ./include/os0file.ic:372
#3 0x00000000007db3de in log_write_up_to (lsn=<value optimized out>,
wait=512, flush_to_disk=1) at log/log0log.c:1512
#4 0x0000000000845911 in trx_commit_complete_for_mysql (trx=0x2aaab0005238)
at trx/trx0trx.c:1607
#5 0x00000000007be3c4 in innobase_commit (hton=<value optimized out>,
thd=0x80e5410, all=false) at handler/ha_innodb.cc:2686
#6 0x00000000006ee11a in ha_commit_trans (thd=0x80e5410, all=false)
at handler.cc:1258
#7 0x00000000007952a5 in trans_commit_stmt (thd=0x80e5410)
at transaction.cc:237
#8 0x00000000005f9dcb in dispatch_command (command=COM_QUERY, thd=0x80e5410,
packet=0x0, packet_length=135364368) at sql_parse.cc:1375
#9 0x00000000005ed9b8 in do_handle_one_connection (
thd_arg=<value optimized out>) at sql_connect.cc:1173
#10 0x00000000005eddba in handle_one_connection (arg=<value optimized out>)
at sql_connect.cc:1112
#11 0x000000000090eb17 in pfs_spawn_thread (arg=<value optimized out>)
at pfs.cc:1011
#12 0x0000003ba88062f7 in start_thread () from /lib64/libpthread.so.0
#13 0x0000003ba80ce85d in clone () from /lib64/libc.so.6
(gdb) thread 3
[Switching to thread 3 (process 9041)]#0 0x0000003ba880a697 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
(gdb) bt
#0 0x0000003ba880a697 in pthread_cond_timedwait@@GLIBC_2.3.2 ()
from /lib64/libpthread.so.0
#1 0x00000000007917f0 in MDL_context::timed_wait (this=0x811dde8,
abs_timeout=0x46508af0) at ../include/mysql/psi/mysql_thread.h:1092
#2 0x00000000007939a9 in MDL_context::acquire_lock_impl (this=0x811dde8,
mdl_request=0x80d9720, lock_wait_timeout=<value optimized out>)
at mdl.cc:1555
#3 0x0000000000793bee in MDL_context::acquire_locks (this=0x811dde8,
mdl_requests=<value optimized out>, lock_wait_timeout=31536000)
at mdl.cc:1654
#4 0x0000000000633698 in open_tables (thd=0x811dd20, start=0x46508ec8,
counter=0x46508edc, flags=32, prelocking_strategy=0x4650ab90)
at sql_base.cc:4443
#5 0x00000000006339ff in open_and_lock_tables (thd=0x811de94,
tables=0x80d93d0, derived=false, flags=4294967295,
prelocking_strategy=0x811de58) at sql_base.cc:5217
#6 0x000000000070422d in mysql_alter_table (thd=0x811dd20,
new_db=0x80d98d8 "test", new_name=0x0, create_info=0x4650bc70,
table_list=0x80d93d0, alter_info=0x4650bd50, order_num=0, order=0x0,
ignore=false) at sql_table.cc:6558
#7 0x00000000005f58fd in mysql_execute_command (thd=0x811dd20)
at sql_parse.cc:2915
#8 0x00000000005f9c45 in mysql_parse (thd=0x811dd20,
inBuf=0x80d92b0 "ALTER TABLE tb0 MODIFY f1 CHAR(255) CHARACTER SET latin1", length=56, found_semicolon=0x4650d060) at sql_parse.cc:5871
#9 0x00000000005fa6b4 in dispatch_command (command=COM_QUERY, thd=0x811dd20,
packet=0x80d1281 "ALTER TABLE tb0 MODIFY f1 CHAR(255) CHARACTER SET latin1", packet_length=<value optimized out>) at sql_parse.cc:1023
#10 0x00000000005ed9b8 in do_handle_one_connection (
thd_arg=<value optimized out>) at sql_connect.cc:1173
#11 0x00000000005eddba in handle_one_connection (arg=<value optimized out>)
at sql_connect.cc:1112
#12 0x000000000090eb17 in pfs_spawn_thread (arg=<value optimized out>)
at pfs.cc:1011
#13 0x0000003ba88062f7 in start_thread () from /lib64/libpthread.so.0
#14 0x0000003ba80ce85d in clone () from /lib64/libc.so.6
As you can see from the trace, the ALTER thread is blocked on a metadata lock.
[6 Apr 2010 12:08]
Konstantin Osipov
16:01 < kostja> marko: hi 16:01 < marko> Hi Kostja! 16:01 < kostja> so my guess is that innodb code is to blame for bug 52580 and 16:02 < kostja> and Bug#52431 16:02 < kostja> what happens is: 16:02 < kostja> ha_innobase::open is calling 16:04 < kostja> innobase_build_index_translation 16:04 < kostja> this function, is accessing INNOBASE_SHARE, in particular: 16:04 < marko> 52431 sure looks like InnoDB bug. The culprit would be Jimmy Yang, who implemented the translation table 16:04 < kostja> index_mapping = share->idx_trans_tbl.index_mapping; 16:05 < kostja> while the other connection is doing: 16:05 < kostja> #0 0x0000003ba880d3b7 in fsync () from /lib64/libpthread.so.0 16:05 < kostja> #1 0x00000000007e8c45 in os_file_flush_func (file=9) at os/os0file.c:2041 16:05 < kostja> #2 0x000000000089c73a in fil_flush (space_id=<value optimized out>) at ./include/os0file.ic:372 16:05 < kostja> #3 0x00000000007db3de in log_write_up_to (lsn=<value optimized out>, wait=512, flush_to_disk=1) at log/log0log.c:1512 16:05 < kostja> #4 0x0000000000845911 in trx_commit_complete_for_mysql (trx=0x2aaab0005238) at trx/trx0trx.c:1607 16:05 < kostja> #5 0x00000000007be3c4 in innobase_commit (hton=<value optimized out>, thd=0x80e5410, all=false) at handler/ha_innodb.cc:2686 16:05 < kostja> #6 0x00000000006ee11a in ha_commit_trans (thd=0x80e5410, all=false) at handler.cc:1258 16:05 < kostja> #7 0x00000000007952a5 in trans_commit_stmt (thd=0x80e5410) at transaction.cc:237 16:05 < kostja> #8 0x00000000005f9dcb in dispatch_command (command=COM_QUERY, thd=0x80e5410, 16:05 < kostja> which I believe somehow changes INNOBASE_SHARE. 16:06 < kostja> previously it didn't crash because the concurrency was much lower, since LOCK_open was held around ha_innobase::open 16:06 < kostja> now we no longer keep lock_open around it and a race has surfaced 16:06 < marko> Sounds plausible. 16:06 < marko> Can you post that to one of the tickets and assign it to Jimmy Yang?
[7 Apr 2010 0:55]
Jimmy Yang
A recent change in bug #51557 removed the protection on ha_innobase::open with mutex LOCK_open protection: === modified file 'sql/sql_base.cc' --- a/sql/sql_base.cc 2010-03-19 10:39:08 +0000 +++ b/sql/sql_base.cc 2010-03-19 10:54:59 +0000 @@ -2914,9 +2914,11 @@ bool open_table(THD *thd, TABLE_LIST *ta while (table_cache_count > table_cache_size && unused_tables) free_cache_entry(unused_tables); + mysql_mutex_unlock(&LOCK_open); + /* make a new table */ if (!(table=(TABLE*) my_malloc(sizeof(*table),MYF(MY_WME)))) - goto err_unlock2; + DBUG_RETURN(TRUE); error= open_table_from_share(thd, share, alias, (uint) (HA_OPEN_KEYFILE | This subsequently cause race condition in ha_innobase::open for building index translation table, which do not use mutex protection as there is already such LOCK_open protection. Fix this by adding mutex protection for index translation table construction.
[14 May 2010 17:45]
Paul DuBois
Not in any released version. No changelog entry needed.
[15 Jun 2010 8:21]
Bugs System
Pushed into 5.5.5-m3 (revid:alik@sun.com-20100615080459-smuswd9ooeywcxuc) (version source revid:mmakela@bk-internal.mysql.com-20100415070122-1nxji8ym4mao13ao) (merge vers: 5.1.47) (pib:16)
[15 Jun 2010 8:38]
Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100615080558-cw01bzdqr1bdmmec) (version source revid:mmakela@bk-internal.mysql.com-20100415070122-1nxji8ym4mao13ao) (pib:16)
Description: Two threads execute simple insert INSERT INTO tb0 (f1) VALUES ('insert'); Another thread alters the table: ALTER TABLE tb0 MODIFY f1 CHAR(255) CHARACTER SET latin2; ALTER TABLE tb0 MODIFY f1 CHAR(255) CHARACTER SET latin1; Server crashes on the concurrent flow: #0 0x0000003ba880b132 in pthread_kill () from /lib64/libpthread.so.0 #1 0x00000000005df45e in handle_segfault (sig=11) at mysqld.cc:2751 #2 <signal handler called> #3 ha_innobase::open (this=0x1c1fedf0, name=0x1c149b90 "./test/tb0", mode=<value optimized out>, test_if_locked=<value optimized out>) at handler/ha_innodb.cc:3382 #4 0x00000000006e94ef in handler::ha_open (this=0x1c1c7433, table_arg=<value optimized out>, name=0x1c149b90 "./test/tb0", mode=2, test_if_locked=24) at handler.cc:2093 #5 0x0000000000637c8a in open_table_from_share (thd=0x1c1c46c0, share=0x1c149830, alias=<value optimized out>, db_stat=0, prgflag=<value optimized out>, ha_open_flags=0, outparam=0x1c1f1e80, is_create_table=false) at table.cc:1916 #6 0x0000000000630697 in open_table (thd=0x1c1c46c0, table_list=0x1c21d158, mem_root=0x464888b0, ot_ctx=0x464888f0, flags=0) at sql_base.cc:2911 #7 0x0000000000632e3b in open_tables (thd=0x1c1c46c0, start=0x464889b8, counter=0x464889cc, flags=0, prelocking_strategy=0x46488bc0) at sql_base.cc:4247 #8 0x00000000006338cf in open_and_lock_tables (thd=0x1c1c7433, tables=0x1c21d158, derived=true, flags=0, prelocking_strategy=0x18) at sql_base.cc:5217 #9 0x000000000066ccd6 in mysql_insert (thd=0x1c1c46c0, table_list=0x1c21d158, fields=@0x1c1c6a08, values_list=@0x1c1c6a50, update_fields=@0x1c1c6a38, update_values=@0x1c1c6a20, duplic=DUP_ERROR, ignore=false) at mysql_priv.h:1608 #10 0x00000000005f60ed in mysql_execute_command (thd=0x1c1c46c0) at sql_parse.cc:3243 #11 0x00000000005f9b15 in mysql_parse (thd=0x1c1c46c0, inBuf=0x1c21d060 "INSERT INTO tb0 (f1) VALUES ('insert')", length=38, found_semicolon=0x4648b060) at sql_parse.cc:5871 #12 0x00000000005fa584 in dispatch_command (command=COM_QUERY, thd=0x1c1c46c0, packet=0x1c215031 "INSERT INTO tb0 (f1) VALUES ('insert')", packet_length=<value optimized out>) at sql_parse.cc:1023 #13 0x00000000005ed888 in do_handle_one_connection (thd_arg=<value optimized out>) at sql_connect.cc:1173 #14 0x00000000005edc8a in handle_one_connection (arg=<value optimized out>) at sql_connect.cc:1112 #15 0x000000000090e017 in pfs_spawn_thread (arg=<value optimized out>) at pfs.cc:1011 #16 0x0000003ba88062f7 in start_thread () from /lib64/libpthread.so.0 #17 0x0000003ba80ce85d in clone () from /lib64/libc.so.6 Could not reproduce on 5.5.3-m3. How to repeat: - unpack the attached archive in <mysql-basedir>/mysql-test. It should create 'stress_test_basedir' folder; - on Linux/Solaris, run as perl ./stress_test_basedir/run.pl