Percona Server moved to https://jira.percona.com/projects/PS

Failing assertion: error == DB_SUCCESS in file handler0alter.cc line 4897 | abort in commit_cache_rebuild

Bug #1213885 reported by Roel Van de Paar
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
Fix Committed
Critical
Laurynas Biveinis
5.1
Fix Committed
Critical
Laurynas Biveinis
5.5
Fix Committed
Critical
Laurynas Biveinis
5.6
Fix Committed
Critical
Laurynas Biveinis

Bug Description

Thread 1 (LWP 12463):
+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 0x0000000000a16610 in commit_cache_rebuild (ctx=0x7f3fa8024ef0) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/storage/innobase/handler/handler0alter.cc:4897
#6 ha_innobase::commit_inplace_alter_table (this=0x7f3ff000e0a0, altered_table=0x7f3f9401c1d0, ha_alter_info=0x7f4006f04970, commit=<optimized out>) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/storage/innobase/handler/handler0alter.cc:5570
#7 0x000000000077ec2f in mysql_inplace_alter_table (thd=0x3c27d60, table_list=0x7f3fa80234b8, table=0x7f3ff0031020, altered_table=0x7f3f9401c1d0, ha_alter_info=0x7f4006f04970, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7f4006f04670, alter_ctx=0x7f4006f03050) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_table.cc:6546
#8 0x0000000000784837 in mysql_alter_table (thd=<optimized out>, new_db=0x7f3f9401c1d0 "\240\312\001\224?\177", new_name=0x7f3f00000000 <Address 0x7f3f00000000 out of bounds>, create_info=<optimized out>, table_list=0x7f3fa80234b8, alter_info=0x7f4006f05110, order_num=0, order=0x0, ignore=false) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_table.cc:8399
#9 0x0000000000894217 in Sql_cmd_alter_table::execute (this=<optimized out>, thd=0x3c27d60) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_alter.cc:317
#10 0x00000000007218eb in mysql_execute_command (thd=0x3c27d60) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_parse.cc:5157
#11 0x00000000007280d8 in mysql_parse (thd=0x3c27d60, rawbuf=0x3c2a120 "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
#12 0x000000000072923c in dispatch_command (command=COM_QUERY, thd=0x3c27d60, packet=0x7f4006f06910 "`}\302\003", packet_length=60) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_parse.cc:1355
#13 0x000000000072a437 in do_command (thd=0x3c27d60) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_parse.cc:1049
#14 0x00000000007d7817 in threadpool_process_request (thd=0x3c27d60) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/sql/threadpool_common.cc:312
#15 0x00000000007da4f8 in handle_event (connection=0x3b42930) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/sql/threadpool_unix.cc:1466
#16 worker_main (param=0x150ce00 <all_groups+512>) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/sql/threadpool_unix.cc:1519
#17 0x00000000009dfc3a in pfs_spawn_thread (arg=0x7f3ff0013310) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/storage/perfschema/pfs.cc:1858
#18 0x000000340cc07851 in start_thread () from /lib64/libpthread.so.0
#19 0x000000340c4e890d in clone () from /lib64/libc.so.6

Version: '5.6.13-rc60.4-debug-log' socket: '/sde/062075/current1_4/tmp/master.sock' port: 13060 Percona Server with XtraDB (GPL), Release rc60.4, Revision 410-debug
InnoDB: Error: 'query112442/t1' is already in tablespace memory cache <<------------------------------------------------------------- (!!!)
2013-08-17 20:30:14 7f4006f07700 InnoDB: Assertion failure in thread 139912971056896 in file handler0alter.cc line 4897
InnoDB: Failing assertion: error == DB_SUCCESS
[...]
Query (7f3fa8023370): ALTER TABLE query112442 . `t1` DROP COLUMN `col_char_32_key`
Connection ID (thread ID): 193
Status: NOT_KILLED

Revision history for this message
Roel Van de Paar (roel11) wrote :
Revision history for this message
Roel Van de Paar (roel11) wrote :
Revision history for this message
Roel Van de Paar (roel11) wrote :
Revision history for this message
Roel Van de Paar (roel11) wrote :
Revision history for this message
Roel Van de Paar (roel11) wrote :
Revision history for this message
Roel Van de Paar (roel11) wrote :

Seen very regular. Almost qablock.

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

100% upstream.

Roel, the paths say 5.6.12. Is this not the QA branch or the current trunk?

tags: added: innodb upstream
Revision history for this message
Roel Van de Paar (roel11) wrote :

Re: 5.6.12 - is QA branch which is at 5.6.12 atm. Ref email

Roel Van de Paar (roel11)
tags: added: qablock
Revision history for this message
Roel Van de Paar (roel11) wrote :

Adding qablock & propose setting this to critical as this is now blocking 5.6 testing; it's crashing almost every trial (have 25500 failures out of 27500 and many of them are due to this bug). If the fix is easy, recommend we fix this and not wait for upstream.

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

Ack

Revision history for this message
Roel Van de Paar (roel11) wrote :

Testing branch provided by Laurynas. Single RQG trial reproduce does not work for this bug; issue likely sporadic. Re-running previous run which should quickly generate a few of these.

Revision history for this message
Roel Van de Paar (roel11) wrote :

Several rounds of patch -> test iteration done and more ongoing.

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :
Download full text (3.2 KiB)

A branch with extra diagnostic output produces this. 13372 and 26985 are thread ids.

(13372) calling fil_rename_tablespace_in_mem query013869/#sql-ib877 to query013869/t1
(26985) calling fil_rename_tablespace_in_mem query013869/#sql-ib875 to query013869/t1
InnoDB: Error: (26985) 'query013869/t1' is already in tablespace memory cache

Thus we have two threads renaming two different temp tables to the same table. The second rename is the expected one from ALTER. Further debugging shows one example stacktrace for the first rename:

Thread 1 (LWP 10362):
+bt
#0 0x000000363720c69c in pthread_kill () from /lib64/libpthread.so.0
#1 0x00000000006870be in handle_fatal_signal (sig=6) at /bzr/bug1213885_dbg/Percona-Server-5.6.12-rc60.4/sql/signal_handler.cc:251
#2 <signal handler called>
#3 0x0000003636e328a5 in raise () from /lib64/libc.so.6
#4 0x0000003636e34085 in abort () from /lib64/libc.so.6
#5 0x0000000000bcc2f1 in fil_rename_tablespace (old_name_in=0x7f374801f068 "query010801/#sql-ib1672", id=1655, new_name=0x7f3736f230eb "query010801/t1", new_path_in=0x0) at /bzr/bug1213885_dbg/Percona-Server-5.6.12-rc60.4/storage/innobase/fil/fil0fil.cc:3151
#6 0x0000000000bccc82 in fil_op_log_parse_or_replay (ptr=0x7f3736f230fa "\002", end_ptr=<optimized out>, type=<optimized out>, space_id=1655, log_flags=<optimized out>) at /bzr/bug1213885_dbg/Percona-Server-5.6.12-rc60.4/storage/innobase/fil/fil0fil.cc:2427
#7 0x0000000000a5bddc in recv_parse_or_apply_log_rec_body (type=34 '"', ptr=0x7f3736f230cf "", end_ptr=0x7f3736f23247 "0801/#sql-ib165\b", block=0x0, mtr=<optimized out>, space_id=<optimized out>) at /bzr/bug1213885_dbg/Percona-Server-5.6.12-rc60.4/storage/innobase/log/log0recv.cc:1321
#8 0x0000000000a5c833 in recv_parse_log_rec (ptr=0x7f3736f230cb "\"\206w", end_ptr=0x7f3736f23247 "0801/#sql-ib165\b", type=0x7f3736f21cbf "\"\200\226U\002", space=0x7f3736f21cb0, page_no=0x7f3736f21ca8, body=<optimized out>) at /bzr/bug1213885_dbg/Percona-Server-5.6.12-rc60.4/storage/innobase/log/log0recv.cc:2188
#9 0x0000000000a595ab in log_online_parse_redo_log () at /bzr/bug1213885_dbg/Percona-Server-5.6.12-rc60.4/storage/innobase/log/log0online.cc:865
#10 log_online_parse_redo_log_block (skip_already_parsed_len=<optimized out>, log_block=0x292fa00 "\200\001\374\023\002") at /bzr/bug1213885_dbg/Percona-Server-5.6.12-rc60.4/storage/innobase/log/log0online.cc:977
#11 log_online_follow_log_seg (block_end_lsn=66659328, block_start_lsn=<optimized out>, group=0x291f628) at /bzr/bug1213885_dbg/Percona-Server-5.6.12-rc60.4/storage/innobase/log/log0online.cc:1037
#12 log_online_follow_log_group (group=0x291f628, contiguous_lsn=66593792) at /bzr/bug1213885_dbg/Percona-Server-5.6.12-rc60.4/storage/innobase/log/log0online.cc:1069
#13 0x0000000000a59aeb in log_online_follow_redo_log () at /bzr/bug1213885_dbg/Percona-Server-5.6.12-rc60.4/storage/innobase/log/log0online.cc:1237
#14 0x0000000000b01af5 in srv_redo_log_follow_thread (arg=<optimized out>) at /bzr/bug1213885_dbg/Percona-Server-5.6.12-rc60.4/storage/innobase/srv/srv0srv.cc:2217
#15 0x0000003637207851 in start_thread () from /lib64/libpthread.so.0
#16 0x0000003636ee890d in clone () from /lib64/libc.so.6

So, it...

Read more...

tags: added: xtradb
removed: innodb upstream
Roel Van de Paar (roel11)
tags: added: 56qual
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.