| Bug #74363 | Assertion failed in commit_try_norebuild (sig 6 in handler0alter.cc:5036) | ||
|---|---|---|---|
| Submitted: | 14 Oct 2014 5:25 | Modified: | 14 Nov 2014 10:26 |
| Reporter: | Ramesh Sivaraman | Email Updates: | |
| Status: | Duplicate | Impact on me: | |
| Category: | MySQL Server: InnoDB storage engine | Severity: | S3 (Non-critical) |
| Version: | 5.6.20-debug | OS: | Linux (CentOS 7) |
| Assigned to: | CPU Architecture: | Any | |
[14 Oct 2014 5:25]
Ramesh Sivaraman
[14 Oct 2014 5:26]
Ramesh Sivaraman
Reducer script
Attachment: reducer42.sh (application/x-shellscript, text), 143.17 KiB.
[14 Oct 2014 5:27]
Ramesh Sivaraman
SQL file
Attachment: pquery_thread-0.sql_out (application/octet-stream, text), 4.42 KiB.
[14 Oct 2014 5:32]
Ramesh Sivaraman
Please modify below parameters before starting reducer script. MYBASE="/ssd/ramesh/mysql-server/mysql-5.6.20-linux-x86_64-debug" INPUTFILE="/ssd/ramesh/411290/42/pquery_thread-0.sql_out"
[14 Oct 2014 5:52]
Ramesh Sivaraman
This issue is reproduced on all mysqld process (started by reducer script). [ramesh@qaserver-01 411290]$ ./reducer42.sh 2014-10-14 05:31:27 [Init] Workdir: /dev/shm/1413264687 2014-10-14 05:31:27 [Init] Temporary storage directory (TMP environment variable) set to /dev/shm/1413264687/tmp 2014-10-14 05:31:27 [Init] Input file: /ssd/ramesh/411290/42/pquery_thread-0.sql_out 2014-10-14 05:31:27 [Init] Server (When MULTI mode is not active): /ssd/ramesh/mysql-server/mysql-5.6.20-linux-x86_64-debug/bin/mysqld (as ramesh) 2014-10-14 05:31:27 [Init] Client (When MULTI mode is not active): /ssd/ramesh/mysql-server/mysql-5.6.20-linux-x86_64-debug/bin/mysql -uroot -S/dev/shm/1413264687/socket.sock 2014-10-14 05:31:27 [Init] Querytimeout: 90 seconds (ensure this is at least 1.5x what was set in RQG using the --querytimeout option) 2014-10-14 05:31:27 [Init] Passing the following additional options to mysqld: --log-output=none --sql_mode=ONLY_FULL_GROUP_BY 2014-10-14 05:31:27 [Init] Setting up standard working subdirectories 2014-10-14 05:31:34 [Init] Loading timezone data into mysql database 2014-10-14 05:31:34 [Info] If you see a GLIBC crash above, change reducer to use a non-Valgrind-instrumented build of mysql_tzinfo_to_sql (Ref. BUG#13498842) 2014-10-14 05:31:41 [Init] Run mode: MODE4: Crash 2014-10-14 05:31:41 [Init] Looking for any mysqld crash 2014-10-14 05:31:41 [Info] Leading [] = No bug/issue found yet | [*] = Bug/issue at least seen once 2014-10-14 05:31:41 [Init] Number of lines in input file: 62 2014-10-14 05:31:41 [] [Stage V] Verifying the bug/issue really exists (duration depends on initial input file size) 2014-10-14 05:31:41 [] [Stage V] [MULTI] Starting 10 verification subreducer threads to verify if the issue is sporadic (/dev/shm/1413264687/subreducer/) 2014-10-14 05:31:44 [] [Stage V] [MULTI] Forking subreducer threads [PIDs]: #1 [32165] #2 [32284] #3 [32413] #4 [32542] #5 [32671] #6 [350] #7 [489] #8 [635] #9 [783] #10 [936] 2014-10-14 05:31:44 [] [Stage V] [MULTI] Waiting for all forked verification subreducer threads to finish/terminate 2014-10-14 05:31:47 [] [Stage V] [MULTI] Finished/Terminated verification subreducer threads: #1 #2 #3 #4 #5 #6 #7 #8 #9 #10 2014-10-14 05:31:47 [] [Stage V] [MULTI] All verification subreducer threads have finished/terminated 2014-10-14 05:31:47 [*] [Stage V] [MULTI] Threads which reproduced the issue: #1 #2 #3 #4 #5 #6 #7 #8 #9 #10 2014-10-14 05:31:47 [*] [Stage V] [MULTI] All threads reproduced the issue: this issue is not sporadic 2014-10-14 05:31:47 [*] [Stage V] [MULTI] Deciding which verified output file to keep out of 10 threads
[14 Oct 2014 8:50]
MySQL Verification Team
That reducer script of yours needs some love ;) Here is the testcase to show the symptom: ---- set global innodb_trx_rseg_n_slots_debug=0; drop table if exists t1; create table t1(a int)engine=innodb; insert into t1 values(1),(2); set global innodb_trx_rseg_n_slots_debug=1; alter table t1 add unique index i1 (a); ----
[15 Oct 2014 0:47]
Roel Van de Paar
Related to bug 74343?
[16 Oct 2014 12:02]
MySQL Verification Team
Hello Ramesh Sivaraman, Thank you for the report. Confirmed with 5.7.6 debug build with Shane's test case. Thanks, Umesh
[16 Oct 2014 12:03]
MySQL Verification Team
// 5.7.6 debug build
[root@cluster-repo mysql-advanced-5.7.6]# bin/mysql -u root -p
Enter password:
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.7.6-m16-enterprise-commercial-advanced-debug MySQL Enterprise Server - Advanced Edition Debug (Commercial)
Copyright (c) 2000, 2014, Oracle and/or its affiliates. All rights reserved.
Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
mysql> set global innodb_trx_rseg_n_slots_debug=0;
Query OK, 0 rows affected (0.00 sec)
mysql> drop table if exists t1;
Query OK, 0 rows affected (0.02 sec)
mysql> create table t1(a int)engine=innodb;
Query OK, 0 rows affected (0.04 sec)
mysql> insert into t1 values(1),(2);
Query OK, 2 rows affected (0.01 sec)
Records: 2 Duplicates: 0 Warnings: 0
mysql> set global innodb_trx_rseg_n_slots_debug=1;
Query OK, 0 rows affected (0.00 sec)
mysql> alter table t1 add unique index i1 (a);
Query OK, 0 rows affected (0.07 sec)
Records: 0 Duplicates: 0 Warnings: 0
mysql> set global innodb_trx_rseg_n_slots_debug=0;
Query OK, 0 rows affected (0.00 sec)
mysql> drop table if exists t1;
Query OK, 0 rows affected (0.02 sec)
mysql> create table t1(a int)engine=innodb;
Query OK, 0 rows affected (0.04 sec)
mysql> insert into t1 values(1),(2);
Query OK, 2 rows affected (0.00 sec)
Records: 2 Duplicates: 0 Warnings: 0
mysql> set global innodb_trx_rseg_n_slots_debug=1;
Query OK, 0 rows affected (0.00 sec)
mysql> alter table t1 add unique index i1 (a);
ERROR 2013 (HY000): Lost connection to MySQL server during query
// extract from error log
mysqld-debug: /pb2/build/sb_0-13146106-1409929295.44/mysqlcom-pro-5.7.6-m16/storage/innobase/handler/handler0alter.cc:5729: bool commit_try_norebuild(Alter_inplace_info*, ha_innobase_inplace_ctx
*, const TABLE*, trx_t*, const char*): Assertion `0' failed.
02:12:56 UTC - mysqld got signal 6 ;
(gdb) bt
#0 0x0000003bf260c8ac in pthread_kill () from /lib64/libpthread.so.0
#1 0x0000000000e794c5 in my_write_core (sig=6) at /pb2/build/sb_0-13146106-1409929295.44/mysqlcom-pro-5.7.6-m16/mysys/stacktrace.c:247
#2 0x000000000086cb4e in handle_fatal_signal (sig=6) at /pb2/build/sb_0-13146106-1409929295.44/mysqlcom-pro-5.7.6-m16/sql/signal_handler.cc:219
#3 <signal handler called>
#4 0x0000003bf2232635 in raise () from /lib64/libc.so.6
#5 0x0000003bf2233e15 in abort () from /lib64/libc.so.6
#6 0x0000003bf222b75e in __assert_fail_base () from /lib64/libc.so.6
#7 0x0000003bf222b820 in __assert_fail () from /lib64/libc.so.6
#8 0x0000000000ecf94e in commit_try_norebuild (ha_alter_info=0x7f953808c850, ctx=0x7f9470006a70, old_table=0x7f9470054d50, trx=0x7f953a29fca0, table_name=0x7f9470055bdd "t1")
at /pb2/build/sb_0-13146106-1409929295.44/mysqlcom-pro-5.7.6-m16/storage/innobase/handler/handler0alter.cc:5729
#9 0x0000000000ecc82d in ha_innobase::commit_inplace_alter_table (this=0x7f94700430d0, altered_table=0x7f9470051220, ha_alter_info=0x7f953808c850, commit=true)
at /pb2/build/sb_0-13146106-1409929295.44/mysqlcom-pro-5.7.6-m16/storage/innobase/handler/handler0alter.cc:6239
#10 0x00000000008d5be6 in handler::ha_commit_inplace_alter_table (this=0x7f94700430d0, altered_table=0x7f9470051220, ha_alter_info=0x7f953808c850, commit=true)
at /pb2/build/sb_0-13146106-1409929295.44/mysqlcom-pro-5.7.6-m16/sql/handler.cc:4475
#11 0x0000000000c1ede2 in mysql_inplace_alter_table (thd=0x7f9470000d30, table_list=0x7f9470005c70, table=0x7f9470054d50, altered_table=0x7f9470051220, ha_alter_info=0x7f953808c850,
inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7f953808d1d0, alter_ctx=0x7f953808bdb0)
at /pb2/build/sb_0-13146106-1409929295.44/mysqlcom-pro-5.7.6-m16/sql/sql_table.cc:6780
#12 0x0000000000c23387 in mysql_alter_table (thd=0x7f9470000d30, new_db=0x7f94700061e8 "test", new_name=0x0, create_info=0x7f953808dc60, table_list=0x7f9470005c70, alter_info=0x7f953808dd40)
at /pb2/build/sb_0-13146106-1409929295.44/mysqlcom-pro-5.7.6-m16/sql/sql_table.cc:8603
#13 0x0000000000d6854f in Sql_cmd_alter_table::execute (this=0x7f94700062b0, thd=0x7f9470000d30) at /pb2/build/sb_0-13146106-1409929295.44/mysqlcom-pro-5.7.6-m16/sql/sql_alter.cc:315
#14 0x0000000000ba8698 in mysql_execute_command (thd=0x7f9470000d30) at /pb2/build/sb_0-13146106-1409929295.44/mysqlcom-pro-5.7.6-m16/sql/sql_parse.cc:4815
#15 0x0000000000baa012 in mysql_parse (thd=0x7f9470000d30, parser_state=0x7f953808f660) at /pb2/build/sb_0-13146106-1409929295.44/mysqlcom-pro-5.7.6-m16/sql/sql_parse.cc:5427
#16 0x0000000000b9dec7 in dispatch_command (command=COM_QUERY, thd=0x7f9470000d30, packet=0x7f94700098b1 "alter table t1 add unique index i1 (a)", packet_length=38)
at /pb2/build/sb_0-13146106-1409929295.44/mysqlcom-pro-5.7.6-m16/sql/sql_parse.cc:1250
#17 0x0000000000b9cb7b in do_command (thd=0x7f9470000d30) at /pb2/build/sb_0-13146106-1409929295.44/mysqlcom-pro-5.7.6-m16/sql/sql_parse.cc:834
#18 0x0000000000caa2d8 in handle_connection (arg=0xd1c5620) at /pb2/build/sb_0-13146106-1409929295.44/mysqlcom-pro-5.7.6-m16/sql/conn_handler/connection_handler_per_thread.cc:298
#19 0x0000000001241f24 in pfs_spawn_thread (arg=0xd1b3220) at /pb2/build/sb_0-13146106-1409929295.44/mysqlcom-pro-5.7.6-m16/storage/perfschema/pfs.cc:2137
#20 0x0000003bf26079d1 in start_thread () from /lib64/libpthread.so.0
#21 0x0000003bf22e886d in clone () from /lib64/libc.so.6
[27 Oct 2014 7:33]
Roel Van de Paar
Another testcase
Attachment: pquery_thread-0.sql_out_out (application/octet-stream, text), 737 bytes.
[7 Nov 2014 17:22]
Ramesh Sivaraman
Found another testcase (similar assertion). ** testcase DROP DATABASE test;CREATE DATABASE test;USE test; create table t1(a int not null,b int not null,index idx(a)); CREATE TABLE t2(a INT KEY,b INT,INDEX ind (b),FOREIGN KEY (b) REFERENCES t1(a) ON DELETE CASCADE ON UPDATE CASCADE) ENGINE=InnoDB; ALTER TABLE t1 CHANGE a id INT; ** GDB info #0 0x00007fa217a8b771 in pthread_kill () from /lib64/libpthread.so.0 #1 0x0000000000a954ea in my_write_core (sig=6) at /ssd/ramesh/mysql-server/mysql-5.6/mysys/stacktrace.c:422 #2 0x0000000000726494 in handle_fatal_signal (sig=6) at /ssd/ramesh/mysql-server/mysql-5.6/sql/signal_handler.cc:230 #3 <signal handler called> #4 0x00007fa2168975c9 in raise () from /lib64/libc.so.6 #5 0x00007fa216898cd8 in abort () from /lib64/libc.so.6 #6 0x0000000000ad524c in ha_innobase::commit_inplace_alter_table (this=0x7fa173098410, altered_table=0x7fa17315ce00, ha_alter_info=0x7fa21803e2f0, commit=true) at /ssd/ramesh/mysql-server/mysql-5.6/storage/innobase/handler/handler0alter.cc:5680 #7 0x000000000063eb01 in handler::ha_commit_inplace_alter_table (this=0x7fa173098410, altered_table=0x7fa17315ce00, ha_alter_info=0x7fa21803e2f0, commit=true) at /ssd/ramesh/mysql-server/mysql-5.6/sql/handler.cc:4386 #8 0x0000000000841126 in mysql_inplace_alter_table (thd=0x7fa18475d000, table_list=0x7fa17301f100, table=0x7fa173051600, altered_table=0x7fa17315ce00, ha_alter_info=0x7fa21803e2f0, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7fa21803dd40, alter_ctx=0x7fa21803e850) at /ssd/ramesh/mysql-server/mysql-5.6/sql/sql_table.cc:6601 #9 0x00000000008452fd in mysql_alter_table (thd=0x7fa18475d000, new_db=0x7fa17301f660 "test", new_name=0x0, create_info=0x7fa21803f6e0, table_list=0x7fa17301f100, alter_info=0x7fa21803f650, order_num=0, order=0x0, ignore=false) at /ssd/ramesh/mysql-server/mysql-5.6/sql/sql_table.cc:8395 #10 0x00000000009849cb in Sql_cmd_alter_table::execute (this=0x7fa17301f730, thd=0x7fa18475d000) at /ssd/ramesh/mysql-server/mysql-5.6/sql/sql_alter.cc:313 #11 0x00000000007d8cbb in mysql_execute_command (thd=0x7fa18475d000) at /ssd/ramesh/mysql-server/mysql-5.6/sql/sql_parse.cc:4945 #12 0x00000000007dbdbc in mysql_parse (thd=0x7fa18475d000, rawbuf=0x7fa17301f010 "ALTER TABLE t1 CHANGE a id INT", length=30, parser_state=0x7fa218040e70) at /ssd/ramesh/mysql-server/mysql-5.6/sql/sql_parse.cc:6245 #13 0x00000000007cf36f in dispatch_command (command=COM_QUERY, thd=0x7fa18475d000, packet=0x7fa179266001 "ALTER TABLE t1 CHANGE a id INT", packet_length=30) at /ssd/ramesh/mysql-server/mysql-5.6/sql/sql_parse.cc:1332 #14 0x00000000007ce45e in do_command (thd=0x7fa18475d000) at /ssd/ramesh/mysql-server/mysql-5.6/sql/sql_parse.cc:1034 #15 0x0000000000796879 in do_handle_one_connection (thd_arg=0x7fa18475d000) at /ssd/ramesh/mysql-server/mysql-5.6/sql/sql_connect.cc:982 #16 0x0000000000796362 in handle_one_connection (arg=0x7fa18475d000) at /ssd/ramesh/mysql-server/mysql-5.6/sql/sql_connect.cc:898 #17 0x0000000000d71288 in pfs_spawn_thread (arg=0x7fa213ffea60) at /ssd/ramesh/mysql-server/mysql-5.6/storage/perfschema/pfs.cc:1860 #18 0x00007fa217a86df3 in start_thread () from /lib64/libpthread.so.0 #19 0x00007fa21695801d in clone () from /lib64/libc.so.6
[14 Nov 2014 10:24]
Marko Mäkelä
Posted by developer: (dberr_t)47 = DB_TOO_MANY_CONCURRENT_TRXS sounds like this was provoked by fault injection with a debug variable. Unfortunately, we cannot do anything about that easily. This is essentially a duplicate of Bug#19947739 DROP TABLE CORRUPTS TABLE The fix for that will be provided by WL#7141 and WL#7016 in the Global Data Dictionary. The "similar assertion" that was reported on Nov 7 is not similar at all. It is an assertion about foreign keys. I filed it as Bug#20031243 ASSERTION FAILURE WHEN RENAMING A COLUMN IN FK PARENT TABLE
[14 Nov 2014 10:26]
Marko Mäkelä
This will be addressed as Bug#74663 DROP TABLE corrupts table and the unrelated test case was filed as Bug#74862 Assertion failure when renaming a column in FK parent table
[14 Nov 2014 20:44]
Roel Van de Paar
Marko, thanks We are 100% sure that the 47 error is caused by set global innodb_trx_rseg_n_slots_debug=0/1; ? Is so, we may need to modify our testing setup. We are seeing the 47 error *a lot*, so as long as we are sure it's caused by this debug setting, we can filter it.
[13 Feb 2015 12:53]
Marko Mäkelä
Roel, I am 99.9% sure that the debug fault injection triggered the message. But, we cannot dismiss this bug because of that. In theory, we can run out of undo log space during DDL operations, and we can corrupt the InnoDB data dictionary or the InnoDB data objects in that case. In DML operations, we always try to write the undo log record first, and any changes will be possible to roll back until the transaction commits. If the undo log record cannot be written, we simply return an error and refuse the operation. Only if the undo log record was successfully written, we will start the actual modifications of the index trees. The DDL operations are currently not working this nicely. By doing destructive operations before commit, we cannot allow the operation to be rolled back. With the current recovery mechanism, we can try to limit the damage, maybe by deferring the operations until after the transaction commit. But then we might leak some space in case the server is killed right after the metadata changes have been committed, before the changes to the data has been made persistent. Our upcoming Global Data Dictionary should fix this class of bugs.
[13 Feb 2015 19:56]
Roel Van de Paar
Thanks Marko
[14 Feb 2015 7:12]
Roel Van de Paar
Marko, you may also want to have a look at bug 74876
[14 Feb 2015 7:20]
Roel Van de Paar
Also see bug 74343
