InnoDB: Failing assertion: strcmp(space->name, old_name) == 0 in in file fil0fil.cc line 3041 | abort in fil_rename_tablespace

[Roel Van de Paar]

2013-06-03 12:11:12 9370 [Note] /ssd/Percona-Server-5.6.11-alpha60.3-372.Linux.x86_64/bin/mysqld: ready for connections.
Version: '5.6.11-alpha60.3-log' socket: '/ssd/084265/current1_4/tmp/master.sock' port: 13060 Percona Server with XtraDB (GPL), Release alpha60.3, Revision 372
2013-06-03 12:29:40 7f848c660700 InnoDB: Assertion failure in thread 140207267907328 in file fil0fil.cc line 3041
InnoDB: Failing assertion: strcmp(space->name, old_name) == 0

Thread 1 (LWP 9674):
+bt
#0 0x0000003fde20c69c in pthread_kill () from /lib64/libpthread.so.0
#1 0x0000000000661f7e in handle_fatal_signal (sig=6) at /bzr/5.6_opt/Percona-Server-5.6.11-alpha60.3/sql/signal_handler.cc:251
#2 <signal handler called>
#3 0x0000003fdde328a5 in raise () from /lib64/libc.so.6
#4 0x0000003fdde34085 in abort () from /lib64/libc.so.6
#5 0x0000000000a8bb46 in fil_rename_tablespace (old_name_in=0x7f848c65baf0 "query19698/#sql-ib649", id=140206968837207, new_name=0x7f8418089d00 "query19698/t3", new_path_in=0x0) at /bzr/5.6_opt/Percona-Server-5.6.11-alpha60.3/storage/innobase/fil/fil0fil.cc:3041
#6 0x0000000000a69cbc in dict_table_rename_in_cache (table=0x7f841805df48, new_name=0x7f8418089d00 "query19698/t3", rename_also_foreigns=0) at /bzr/5.6_opt/Percona-Server-5.6.11-alpha60.3/storage/innobase/dict/dict0dict.cc:1510
#7 0x0000000000945bb7 in commit_cache_rebuild (ctx=0x7f8418005630) at /bzr/5.6_opt/Percona-Server-5.6.11-alpha60.3/storage/innobase/handler/handler0alter.cc:4892
#8 ha_innobase::commit_inplace_alter_table (this=<optimized out>, altered_table=0x7f841808b780, ha_alter_info=0x7f848c65ddb0, commit=<optimized out>) at /bzr/5.6_opt/Percona-Server-5.6.11-alpha60.3/storage/innobase/handler/handler0alter.cc:5566
#9 0x000000000072ec75 in mysql_inplace_alter_table (thd=0x3114700, table_list=0x7f8418004bf8, table=0x7f841808e410, altered_table=0x7f841808b780, ha_alter_info=0x7f848c65ddb0, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7f848c65db20, alter_ctx=0x7f848c65c500) at /bzr/5.6_opt/Percona-Server-5.6.11-alpha60.3/sql/sql_table.cc:6527
#10 0x0000000000730fe7 in mysql_alter_table (thd=<optimized out>, new_db=0x7f848c65e520 "", new_name=<optimized out>, create_info=<optimized out>, table_list=0x7f8418004bf8, alter_info=<optimized out>, order_num=0, order=0x0, ignore=false) at /bzr/5.6_opt/Percona-Server-5.6.11-alpha60.3/sql/sql_table.cc:8369
#11 0x0000000000818957 in Sql_cmd_alter_table::execute (this=<optimized out>, thd=0x3114700) at /bzr/5.6_opt/Percona-Server-5.6.11-alpha60.3/sql/sql_alter.cc:317
#12 0x00000000006de1b0 in mysql_execute_command (thd=0x3114700) at /bzr/5.6_opt/Percona-Server-5.6.11-alpha60.3/sql/sql_parse.cc:5132
#13 0x00000000006e1568 in mysql_parse (thd=0x3114700, rawbuf=<optimized out>, length=51473032, parser_state=<optimized out>) at /bzr/5.6_opt/Percona-Server-5.6.11-alpha60.3/sql/sql_parse.cc:6451
#14 0x00000000006e2421 in dispatch_command (command=COM_QUERY, thd=0x3114700, packet=0x3078e61 "ALTER TABLE query19698 . `t3` DROP COLUMN `c57`", packet_length=47) at /bzr/5.6_opt/Percona-Server-5.6.11-alpha60.3/sql/sql_parse.cc:1376
#15 0x00000000006b006f in do_handle_one_connection (thd_arg=<optimized out>) at /bzr/5.6_opt/Percona-Server-5.6.11-alpha60.3/sql/sql_connect.cc:1615
#16 0x00000000006b0147 in handle_one_connection (arg=<optimized out>) at /bzr/5.6_opt/Percona-Server-5.6.11-alpha60.3/sql/sql_connect.cc:1526
#17 0x00000000009196a9 in pfs_spawn_thread (arg=0x3085da0) at /bzr/5.6_opt/Percona-Server-5.6.11-alpha60.3/storage/perfschema/pfs.cc:1853
#18 0x0000003fde207851 in start_thread () from /lib64/libpth

[Roel Van de Paar (roel11)]

Very low frequency crash, at least with current grammar

[Laurynas Biveinis (laurynas-biveinis)]

Looks like an upstream issue. Should be reproduced and reported there.

[Roel Van de Paar (roel11)]

Query (7f8418004ad0): ALTER TABLE query19698 . `t3` DROP COLUMN `c57`
And, seen again in another run for:
Query (1f9c9ab0): ALTER TABLE query024802 . `t1` DROP COLUMN `c4`

[Roel Van de Paar (roel11)]

Adding another type of occurrence (different stack):

Thread 1 (LWP 8032):
+bt
#0 0x000000340cc0c69c in pthread_kill () from /lib64/libpthread.so.0
#1 0x0000000000686ffe in handle_fatal_signal (sig=6) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/sql/signal_handler.cc:251
#2 <signal handler called>
#3 0x000000340c4328a5 in raise () from /lib64/libc.so.6
#4 0x000000340c434085 in abort () from /lib64/libc.so.6
#5 0x0000000000bcb23a in fil_rename_tablespace (old_name_in=0x7f3cb0009c68 "query18053/#sql2-1e24-50", id=42, new_name=0x7f3d006ed0c0 "query18053/t1", new_path_in=0x0) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/storage/innobase/fil/fil0fil.cc:3111
#6 0x0000000000ba1a50 in dict_table_rename_in_cache (table=0x7f3c7c00e4b8, new_name=0x7f3d006ed0c0 "query18053/t1", rename_also_foreigns=1) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/storage/innobase/dict/dict0dict.cc:1514
#7 0x0000000000acf154 in row_rename_table_for_mysql (old_name=<optimized out>, new_name=<optimized out>, trx=0x7f3cb006c0e8, commit=<optimized out>) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/storage/innobase/row/row0mysql.cc:5029
#8 0x0000000000a09cb0 in innobase_rename_table (to=0x7f3d006ed9b0 "./query18053/t1", from=0x7f3d006edbc0 "./query18053/#sql2-1e24-50", trx=0x7f3cb006c0e8) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/storage/innobase/handler/ha_innodb.cc:10560
#9 ha_innobase::rename_table (this=<optimized out>, from=0x7f3d006edbc0 "./query18053/#sql2-1e24-50", to=0x7f3d006ed9b0 "./query18053/t1") at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/storage/innobase/handler/ha_innodb.cc:10678
#10 0x0000000000775537 in mysql_rename_table (base=<optimized out>, old_db=0x7f3cb00059f8 "query18053", old_name=0x7f3d006ef9e0 "#sql2-1e24-50", new_db=0x7f3cb00059f8 "query18053", new_name=0x7f3cb0005a10 "t1", flags=65) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_table.cc:5169
#11 0x00000000007844b5 in mysql_alter_table (thd=<optimized out>, new_db=0x7f3d006ef820 "", new_name=0x7f3cb000bde0 "`\003\001\260<\177", create_info=<optimized out>, table_list=0x7f3cb0005a48, alter_info=0x7f3d006f0110, order_num=0, order=0x0, ignore=false) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_table.cc:8677
#12 0x0000000000894217 in Sql_cmd_alter_table::execute (this=<optimized out>, thd=0x1f39c20) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_alter.cc:317
#13 0x00000000007218eb in mysql_execute_command (thd=0x1f39c20) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_parse.cc:5157
#14 0x00000000007280d8 in mysql_parse (thd=0x1f39c20, rawbuf=0x1f3bfe0 "P\303\067\001", length=<optimized out>, parser_state=<optimized out>) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_parse.cc:6477
#15 0x000000000072923c in dispatch_command (command=COM_QUERY, thd=0x1f39c20, packet=0x7f3d006f1910 " \234\363\001", packet_length=46) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_parse.cc:1355
#16 0x000000000072a437 in do_command (thd=0x1f39c20) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_parse.cc:1049
#17 0x00000000007d7817 in threadpool_process_request (thd=0x1f39c20) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/sql/thre...

[Roel Van de Paar (roel11)]

Laurynas, would you mind having a look at the additional stacks to confirm it's upstream? Note the InnoDB error (which is also seen in bug 1213885) just before the assert

[Laurynas Biveinis (laurynas-biveinis)]

This is upstream (and the InnoDB error before the crash is upstream too). This is a threadpool run, but threadpool is not related (the previous cases were without threadpool right?)

[Roel Van de Paar (roel11)]

Confirmed that original case is w/o threadpool

[roel@qaserver 084265]$ cat vardir1_28/command
bash -c "set -o pipefail; perl runall.pl --queries=100000000 --seed=random --duration=120 --querytimeout=60 --short_column_names --reporter=Shutdown,Backtrace,QueryTimeout,ErrorLog,ErrorLogAlarm --mysqld=--log-output=none --mysqld=--sql_mode=ONLY_FULL_GROUP_BY --grammar=conf/percona_qa/5.6/5.6.yy --gendata=conf/percona_qa/5.6/5.6.zz --basedir=/ssd/Percona-Server-5.6.11-alpha60.3-372.Linux.x86_64 --threads=25 --views --notnull --validator=Transformer --mysqld=--slow_query_log --mysqld=--innodb_track_changed_pages=1 --mysqld=--innodb_max_bitmap_file_size=20480 --mysqld=--innodb_changed_pages=ON --mysqld=--innodb_max_changed_pages=0 --mysqld=--userstat --mysqld=--innodb_log_file_size=10485761 --mysqld=--innodb_log_files_in_group=3 --mysqld=--innodb_log_buffer_size=1048577
 --mysqld=--innodb_log_block_size=4096 --mysqld=--innodb_fast_shutdown=0 --mysqld=--skip-innodb_doublewrite --mysqld=--userstat --mtr-build-thread=306 --mask=51125 --vardir1=/ssd/084265/current1_4 > /ssd/084265/trial28.log 2>&1"

[Roel Van de Paar (roel11)]

Laurynas, if it makes any difference/is still of interest (re: upstream), this was also seen in Percona-Server-5.6.12-rc60.4-415-debug.Linux.x86_64, the patch branch provided for bug 1213885.

[Laurynas Biveinis (laurynas-biveinis)]

Both runs have changed page tracking enabled. This makes it more likely to be another case of the issue in bug 1213885 and bug 1217002 than upstream. Roel, does this occur on a recent QA branch with these two bugs fixed?

[Roel Van de Paar (roel11)]

Cannot see it in recent runs anymore

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-674