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
2014-10-14 05:06:29 31090 [Note] /ssd/ramesh/mysql-server/mysql-5.6.20-linux-x86_64-debug/bin/mysqld: ready for connections.
Version: '5.6.20-debug'  socket: '/ssd/ramesh/mysql-server/mysql-5.6.20-linux-x86_64-debug/socket.sock'  port: 19805  MySQL Community Server (GPL)
2014-10-14 05:06:36 7f06e766b700  InnoDB: Warning: cannot find a free slot for an undo log. Do you have too
InnoDB: many active transactions running concurrently?
2014-10-14 05:06:36 7f06e766b700 InnoDB: Error: row_merge_rename_index_to_add failed with error code: 47.
2014-10-14 05:06:36 31090 [ERROR] InnoDB: rename index to add: 47

mysqld: /ssd/ramesh/mysql-server/mysql-5.6/storage/innobase/handler/handler0alter.cc:5036: bool commit_try_norebuild(Alter_inplace_info*, ha_innobase_inplace_ctx*, const TABLE*, trx_t*, const char*): Assertion `0' failed.
05:06:36 UTC - mysqld got signal 6 ;

******* gdb
#0  0x00007f06e7072771 in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000000a9035e in my_write_core (sig=6) at /ssd/ramesh/mysql-server/mysql-5.6/mysys/stacktrace.c:422
#2  0x0000000000723688 in handle_fatal_signal (sig=6) at /ssd/ramesh/mysql-server/mysql-5.6/sql/signal_handler.cc:230
#3  <signal handler called>
#4  0x00007f06e5e7e5c9 in raise () from /lib64/libc.so.6
#5  0x00007f06e5e7fcd8 in abort () from /lib64/libc.so.6
#6  0x00007f06e5e77536 in __assert_fail_base () from /lib64/libc.so.6
#7  0x00007f06e5e775e2 in __assert_fail () from /lib64/libc.so.6
#8  0x0000000000b7385d in commit_try_norebuild (ha_alter_info=0x7f06e7667a60, ctx=0x7f062cc1fb90, old_table=0x7f062ae77e00, trx=0x7f06cb3bc678, table_name=0x7f062cc9cf35 "t6") at /ssd/ramesh/mysql-server/mysql-5.6/storage/innobase/handler/handler0alter.cc:5036
#9  0x0000000000b70bc0 in ha_innobase::commit_inplace_alter_table (this=0x7f063dfed010, altered_table=0x7f06e507f800, ha_alter_info=0x7f06e7667a60, commit=true) at /ssd/ramesh/mysql-server/mysql-5.6/storage/innobase/handler/handler0alter.cc:5479
#10 0x000000000063c055 in handler::ha_commit_inplace_alter_table (this=0x7f063dfed010, altered_table=0x7f06e507f800, ha_alter_info=0x7f06e7667a60, commit=true) at /ssd/ramesh/mysql-server/mysql-5.6/sql/handler.cc:4386
#11 0x000000000083e2a6 in mysql_inplace_alter_table (thd=0x7f063dfdb000, table_list=0x7f062cc1f100, table=0x7f062ae77e00, altered_table=0x7f06e507f800, ha_alter_info=0x7f06e7667a60, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7f06e76674b0, alter_ctx=0x7f06e7667fc0) at /ssd/ramesh/mysql-server/mysql-5.6/sql/sql_table.cc:6601
#12 0x000000000084247d in mysql_alter_table (thd=0x7f063dfdb000, new_db=0x7f062cc1f660 "test", new_name=0x7f062cc1f0c8 "t6", create_info=0x7f06e76693d0, table_list=0x7f062cc1f100, alter_info=0x7f06e7668e70, order_num=0, order=0x0, ignore=false) at /ssd/ramesh/mysql-server/mysql-5.6/sql/sql_table.cc:8395
#13 0x00000000007d0673 in mysql_execute_command (thd=0x7f063dfdb000) at /ssd/ramesh/mysql-server/mysql-5.6/sql/sql_parse.cc:3106
#14 0x00000000007d8fa4 in mysql_parse (thd=0x7f063dfdb000, rawbuf=0x7f062cc1f010 "CREATE INDEX i1 ON t6(c1)", length=25, parser_state=0x7f06e7669e70) at /ssd/ramesh/mysql-server/mysql-5.6/sql/sql_parse.cc:6245
#15 0x00000000007cc557 in dispatch_command (command=COM_QUERY, thd=0x7f063dfdb000, packet=0x7f063dfe4001 "CREATE INDEX i1 ON t6(c1)", packet_length=25) at /ssd/ramesh/mysql-server/mysql-5.6/sql/sql_parse.cc:1332
#16 0x00000000007cb646 in do_command (thd=0x7f063dfdb000) at /ssd/ramesh/mysql-server/mysql-5.6/sql/sql_parse.cc:1034
#17 0x0000000000793a61 in do_handle_one_connection (thd_arg=0x7f063dfdb000) at /ssd/ramesh/mysql-server/mysql-5.6/sql/sql_connect.cc:982
#18 0x000000000079354a in handle_one_connection (arg=0x7f063dfdb000) at /ssd/ramesh/mysql-server/mysql-5.6/sql/sql_connect.cc:898
#19 0x0000000000ad4b5c in pfs_spawn_thread (arg=0x7f06e53d7b00) at /ssd/ramesh/mysql-server/mysql-5.6/storage/perfschema/pfs.cc:1860
#20 0x00007f06e706ddf3 in start_thread () from /lib64/libpthread.so.0
#21 0x00007f06e5f3f01d in clone () from /lib64/libc.so.6
(gdb) +set logging off

****** perror
$ ./bin/perror 47
OS error code  47:  Level 3 reset

How to repeat:
Please find the attached reducer script to reproduce the issue.
[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.

[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.

[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

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

create table t1(a int not null,b int not null,index idx(a));

** 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:
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

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
[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