| Bug #45808 | crash during concurrent inserts and partition management statements | ||
|---|---|---|---|
| Submitted: | 28 Jun 2009 14:11 | Modified: | 18 Jan 2010 16:50 |
| Reporter: | Shane Bester (Platinum Quality Contributor) | Email Updates: | |
| Status: | Duplicate | Impact on me: | |
| Category: | MySQL Server: Partitions | Severity: | S1 (Critical) |
| Version: | 5.1.34, 5.1.37, 6.0.12 | OS: | Any |
| Assigned to: | Assigned Account | CPU Architecture: | Any |
| Tags: | regression | ||
[28 Jun 2009 14:11]
Shane Bester
[29 Jun 2009 13:51]
MySQL Verification Team
start server with options:
--innodb_lock_wait_timeout=1 --innodb_flush_log_at_trx_commit=0
Try use a very fast server, or non-debug build for easiest repeatability.
testcase, using stored routine
------------------------------
delimiter ;
drop table if exists `t1`;
create table `t1`(`id` tinyint not null primary key)engine=innodb;
drop procedure if exists `p1`;
delimiter //
create procedure `p1`(`repeat_count` int)
begin
declare `i` int default 0;
declare continue handler for sqlexception begin end;
repeat
start transaction;
insert ignore into t1(id) values (5);
delete from t1 where id=5;
commit;
alter table t1 partition by key () partitions 6;
alter table t1 coalesce partition 5;
set `i`=`i`+1;
until `i`>=`repeat_count`
end repeat;
end //
delimiter ;
call `p1`(10000); #call this in two connections
[29 Jun 2009 14:00]
Valeriy Kravchuk
With 5.1.37-debug on Mac I've got assertion instead: 090629 16:57:44 InnoDB: Assertion failure in thread 2955325440 in file row/row0mysql.c line 1677 InnoDB: Failing assertion: index
[29 Jun 2009 14:02]
MySQL Verification Team
not sure if this is innodb/partitioning/locking bug. set category/lead as appropriate.
[2 Jul 2009 10:15]
MySQL Verification Team
This crash doesn't happen when innodb_files_per_table=ON.
[14 Jul 2009 7:17]
MySQL Verification Team
Hi, I tested on my machine and got the crash like below: (gdb) bt #0 0x00007f0372e191f6 in pthread_kill () from /lib/libpthread.so.0 #1 0x00000000006480a9 in handle_segfault (sig=11) at mysqld.cc:2536 #2 <signal handler called> #3 row_get_mysql_key_number_for_index (index=0x150) at ../../storage/innobase/include/dict0dict.ic:156 #4 0x000000000080d23c in ha_innobase::info (this=0xd9be5b0, flag=<value optimized out>) at handler/ha_innodb.cc:6191 #5 0x00000000007405f0 in ha_partition::info (this=0xd98e830, flag=<value optimized out>) at ha_partition.cc:4934 #6 0x0000000000738782 in handler::get_dup_key (this=0xd9be5b0, error=<value optimized out>) at handler.cc:2935 #7 0x000000000073b59d in handler::print_error (this=0xd9be5b0, error=336, errflag=0) at handler.cc:2593 #8 0x000000000057f0be in mysql_change_partitions (lpt=0x7f021616f710) at sql_partition.cc:5098 #9 0x0000000000584bcd in fast_alter_partition_table (thd=0xd9abc80, table=0xd9547c0, alter_info=<value optimized out>, create_info=<value optimized out>, table_list=0xd9d0ab0, db=<value optimized out>, table_name=0xd9cf838 "t1", fast_alter_partition=1) at sql_partition.cc:6327 #10 0x0000000000753aef in mysql_alter_table (thd=0xd9abc80, new_db=0xd9c3190 "test", new_name=0xd9cf838 "t1", create_info=0x7f0216172700, table_list=0xd9d0ab0, alter_info=0x7f02161727e0, order_num=0, order=0x0, ignore=false) at sql_table.cc:6653 #11 0x00000000006597ea in mysql_execute_command (thd=0xd9abc80) at sql_parse.cc:2856 #12 0x00000000007a40ce in sp_instr_stmt::exec_core (this=0xd9cf878, thd=0x0, nextp=0x7f036e20b8b8) at sp_head.cc:2904 #13 0x00000000007a8645 in sp_lex_keeper::reset_lex_and_exec_core (this=0xd9cf8b8, thd=0xd9abc80, nextp=0x7f02161731e8, open_tables=false, instr=0xd9cf878) at sp_head.cc:2732 #14 0x00000000007a9315 in sp_instr_stmt::execute (this=0xd9cf878, thd=0xd9abc80, nextp=0x7f02161731e8) at sp_head.cc:2846 #15 0x00000000007a67d3 in sp_head::execute (this=0xd9c2cf0, thd=0xd9abc80) at sp_head.cc:1252 #16 0x00000000007a6e6c in sp_head::execute_procedure (this=0xd9c2cf0, thd=0xd9abc80, args=0xd9adf90) at sp_head.cc:1981 #17 0x000000000065ac2c in mysql_execute_command (thd=0xd9abc80) at sql_parse.cc:4323 #18 0x000000000065e747 in mysql_parse (thd=0xd9abc80, inBuf=0xd9ae550 "call p1(10000)", length=14, found_semicolon=0x7f0216174ac0) at sql_parse.cc:5902 #19 0x000000000065f7df in dispatch_command (command=COM_QUERY, thd=0xd9abc80, packet=0xd9b5d11 "call p1(10000)", packet_length=<value optimized out>) at sql_parse.cc:1216 #20 0x000000000065ff8e in do_command (thd=0xd9abc80) at sql_parse.cc:857 #21 0x000000000065240d in handle_one_connection (arg=<value optimized out>) at sql_connect.cc:1115 #22 0x00007f0372e143ba in start_thread () from /lib/libpthread.so.0 #23 0x00007f037208dfcd in clone () from /lib/libc.so.6 #24 0x0000000000000000 in ?? () You can see mysql_change_partitions() calls handler::print_error(), then it calls handler::get_dup_key(). However, the error must be false because the table is empty when altering the table. (I use the same stored procedure provided by Shane) Since the error is false, so row_get_mysql_key_number_for_index() accesses the false location, then it results in a crash. Before mysql_change_partitions() calls handler::print_error(), it calls handler::ha_change_partition(), and it calls handler:change_partitions(), then it calls handler::copy_partitions(). So, handler::print_error() is called when handler::copy_partitions() returns an error, and the error is HA_ERR_FOUND_DUPP_KEY.
[14 Jul 2009 8:31]
MySQL Verification Team
Tracefile before crash
Attachment: trace-crash-partitions.txt (text/plain), 5.84 KiB.
[14 Jul 2009 8:38]
MySQL Verification Team
Please see the attachment above. According to the trace file, ha_innobase::create somehow fails.
[6 Aug 2009 9:30]
Marko Mäkelä
The cause of the bug mentioned at [14 Jul 9:17] is uninitialized trx->error_info. I reduced the probability of that by assigning trx->error_info = NULL; in trx_create(). However, that bug still repeats. Presumably, trx->error_info should be zeroed out at commit and rollback. Another bug that I found is that ha_partition::close() is apparently calling ha_innobase::close() twice, causing an assertion failure in row_prebuilt_free(). I will take care of the corrupted trx->error_info, and I will try to narrow down the cause of the ha_partition::close() bug. The original stack trace could be a sign of a yet another bug, though.
[6 Aug 2009 10:39]
Marko Mäkelä
This bug seems to be caused by garbage in trx->error_info. Clearing it at both trx_create() and trx_commit_off_kernel() fixes all crashes for me: Index: trx/trx0trx.c =================================================================== --- trx/trx0trx.c (revision 5634) +++ trx/trx0trx.c (working copy) @@ -140,6 +140,7 @@ trx_create( trx->undo_no_arr = NULL; trx->error_state = DB_SUCCESS; + trx->error_info = NULL; trx->error_key_num = 0; trx->detailed_error[0] = '\0'; @@ -940,6 +941,7 @@ trx_commit_off_kernel( trx->undo_no = ut_dulint_zero; trx->last_sql_stat_start.least_undo_no = ut_dulint_zero; trx->mysql_query_str = NULL; + trx->error_info = NULL; ut_ad(UT_LIST_GET_LEN(trx->wait_thrs) == 0); ut_ad(UT_LIST_GET_LEN(trx->trx_locks) == 0); At trx_commit_off_kernel(), we might also want to clear error_state, error_key_num and detailed_error at commit, among other things.
[7 Sep 2009 8:38]
Mattias Jonsson
Analyzing if it is a duplicate of bug#47029. (waiting on the solution on that bug.)
[7 Sep 2009 19:29]
Mattias Jonsson
The error code HA_ERR_FOUND_DUPP_KEY comes from ha_innobase::create, since the table already seems to exists in the InnoDB Data dictionary (innodb internal error code om create_table_def was 17 - DB_DUPLICATE_KEY, which gets translated by convert_error_code_to_mysql into HA_ERR_FOUND_DUPP_KEY).
I could not avoid the crash using the patch setting trx->error_info = NULL:
InnoDB: Assertion failure in thread 4349378560 in file row/row0mysql.c line 1682
InnoDB: Failing assertion: index
Is there someway to flush the dropped partitions (tables) in InnoDB?
By applying this patch the crash is avoided, but the log is flooded by errors:
partitioning patch:
=== modified file 'sql/ha_partition.cc'
--- sql/ha_partition.cc 2009-09-04 03:57:11 +0000
+++ sql/ha_partition.cc 2009-09-07 19:06:01 +0000
@@ -1220,7 +1220,11 @@
0, p_elem)))
goto error;
if ((error= file->ha_create(part_name, tbl, create_info)))
+ {
+ if (error == HA_ERR_FOUND_DUPP_KEY)
+ error= HA_ERR_TABLE_EXIST;
goto error;
+ }
create_flag= TRUE;
if ((error= file->ha_open(tbl, part_name, m_mode, m_open_test_lock)))
goto error;
flooded logs:
090907 21:04:51 InnoDB: Error: table `test`.090907 21:04:51 [ERROR] Invalid (old?) table or database name 't1#P#p0#TMP#'
`#mysql50#t1#P#p0#TMP#` already exists in InnoDB internal
InnoDB: data dictionary. Have you deleted the .frm file
InnoDB: and not used DROP TABLE? Have you used DROP DATABASE
InnoDB: for InnoDB tables in MySQL version <= 3.23.43?
InnoDB: See the Restrictions section of the InnoDB manual.
...
Trace:
1936 ut_print_timestamp(stderr);
(gdb) bt
#0 row_create_table_for_mysql (table=0x1019da0a8, trx=0x1019b48a8) at row/row0mysql.c:1936
#1 0x00000001004284ed in create_table_def (trx=0x1019b48a8, form=0x1010a9628, table_name=0x1033debe0 "test/t1#P#p0#TMP#", path_of_temp_table=0x0, flags=1) at handler/ha_innodb.cc:5146
#2 0x0000000100428c13 in ha_innobase::create (this=0x1010e3280, name=0x1033df170 "./test/t1#P#p0#TMP#", form=0x1010a9628, create_info=0x1033e10b0) at handler/ha_innodb.cc:5434
#3 0x0000000100253993 in handler::ha_create (this=0x1010e3280, name=0x1033df170 "./test/t1#P#p0#TMP#", form=0x1010a9628, info=0x1033e10b0) at handler.cc:3368
#4 0x000000010025acc4 in ha_partition::prepare_new_partition (this=0x1010b7838, tbl=0x1010a9628, create_info=0x1033e10b0, file=0x1010e3280, part_name=0x1033df170 "./test/t1#P#p0#TMP#", p_elem=0x1010b7f10) at ha_partition.cc:1222
#5 0x000000010025b85b in ha_partition::change_partitions (this=0x1010b7838, create_info=0x1033e10b0, path=0x1033df510 "./test/t1", copied=0x1033dfae0, deleted=0x1033dfae8, pack_frm_data=0x0, pack_frm_len=0) at ha_partition.cc:1555
#6 0x0000000100253a54 in handler::ha_change_partitions (this=0x1010b7838, create_info=0x1033e10b0, path=0x1033df510 "./test/t1", copied=0x1033dfae0, deleted=0x1033dfae8, pack_frm_data=0x0, pack_frm_len=0) at handler.cc:3405
#7 0x0000000100014353 in mysql_change_partitions (lpt=0x1033df7b0) at sql_partition.cc:5143
#8 0x000000010001767a in fast_alter_partition_table (thd=0x101036a28, table=0x1010a9628, alter_info=0x1033e19b0, create_info=0x1033e10b0, table_list=0x1010d6588, db=0x1010c96d8 "test", table_name=0x1010d5330 "t1", fast_alter_partition=1) at sql_partition.cc:6380
#9 0x0000000100279b91 in mysql_alter_table (thd=0x101036a28, new_db=0x1010c96d8 "test", new_name=0x1010d5330 "t1", create_info=0x1033e10b0, table_list=0x1010d6588, alter_info=0x1033e19b0, order_num=0, order=0x0, ignore=false) at sql_table.cc:7021
...
testfile (b45808.test):
--source include/have_innodb.inc
--source include/have_partition.inc
--disable_warnings
drop table if exists `t1`;
drop procedure if exists `p1`;
--enable_warnings
create table `t1`(`id` tinyint not null primary key)engine=innodb;
SHOW CREATE TABLE t1;
delimiter //;
create procedure `p1`(`repeat_count` int)
begin
declare `i` int default 0;
declare continue handler for sqlexception begin end;
repeat
start transaction;
insert ignore into t1(id) values (5);
delete from t1 where id=5;
commit;
alter table t1 partition by key () partitions 6;
alter table t1 coalesce partition 5;
set `i`=`i`+1;
until `i`>=`repeat_count`
end repeat;
end //
delimiter ;//
--echo # call this in two connections (First)
send call `p1`(10000);
connect (con2, localhost, root,,);
--echo # call this in two connections (Second)
call `p1`(10000);
disconnect con2;
connection default;
reap;
drop procedure p1;
drop table t1;
opt-file (b45808-master.opt):
--innodb_lock_wait_timeout=1 --innodb_flush_log_at_trx_commit=0
[7 Sep 2009 19:38]
Mattias Jonsson
Mikaels analysis of bug#47029 (which seems related to this bug): My analysis so far shows that an already deleted table is still in the InnoDB dictionary for some reason. I still have to investigate why this is the case. However when InnoDB reports the error code for this it uses the error code for DUPLICATE KEY which isn't so good. The partitioning code calls print_error on the InnoDB handler with this error code and this in turn leads to a call of get_dup_key. This eventually leads to a crash since InnoDB rightly assumes that get_dup_key is only called on an open handler. However rename_table is called on a closed handler. Thus InnoDB should report a different error code from rename_table to ensure that MySQL doesn't crash. Same goes also for delete_table although I haven't analysed the InnoDB code there.
[11 Sep 2009 22:49]
Calvin Sun
This is a duplicate of 47029. The fix is in partitioning. As for returning a different error code, bug#45961 will be used, based on discussion between Mikael and Jimmy.
