Bug #35080 Innodb crash at mem_block_get_len line 72
Submitted: 5 Mar 2008 13:00 Modified: 26 Feb 2010 9:57
Reporter: Philip Stoev Email Updates:
Status: Duplicate Impact on me:
None 
Category:MySQL Server: Optimizer Severity:S3 (Non-critical)
Version:6.0-falcon-team,6.0 OS:Any
Assigned to: Assigned Account CPU Architecture:Any
Tags: ICP, index_condition_pushdown, optimizer_switch, v6

[5 Mar 2008 13:00] Philip Stoev
Description:
When executing a concurrent workload, innodb crashed as follows:

#0  0x00110402 in __kernel_vsyscall ()
#1  0x00bdc617 in pthread_kill () from /lib/libpthread.so.0
#2  0x0842ba24 in write_core (sig=11) at stacktrace.c:240
#3  0x082912a6 in handle_segfault (sig=11) at mysqld.cc:2313
#4  <signal handler called>
#5  0x085ec8fc in mem_block_get_len (block=0xff) at ../../storage/innobase/include/mem0mem.ic:72
#6  0x085ece39 in mem_heap_get_size (heap=0xb7082d28) at ../../storage/innobase/include/mem0mem.ic:563
#7  0x085c0c57 in dict_table_remove_from_cache (table=0xb708de68) at dict/dict0dict.c:1236
#8  0x0860969b in row_drop_table_for_mysql (name=0xb707f268 "tmp/#sql2180_4f_4", trx=0xb7087068, drop_db=0) at row/row0mysql.c:3250
#9  0x085a739b in ha_innobase::delete_table (this=0xb014ba8, name=0xb2500d88 "/build/mysql-6.0-falcon-team/mysql-test/var/tmp/#sql2180_4f_4")
    at handler/ha_innodb.cc:5268
#10 0x082e3c70 in rm_temporary_table (base=0xa861de0, path=0xb2500d88 "/build/mysql-6.0-falcon-team/mysql-test/var/tmp/#sql2180_4f_4", frm_only=false)
    at sql_base.cc:5372
#11 0x082e6ee8 in close_temporary (table=0xb2500480, free_share=true, delete_table=true) at sql_base.cc:1926
#12 0x082e7774 in close_temporary_tables (thd=0xaff2f00) at sql_base.cc:1539
#13 0x0827b309 in THD::cleanup (this=0xaff2f00) at sql_class.cc:684
#14 0x082914e6 in unlink_thd (thd=0xaff2f00) at mysqld.cc:1787
#15 0x082915a1 in one_thread_per_connection_end (thd=0xaff2f00, put_in_cache=true) at mysqld.cc:1869
#16 0x08299d97 in handle_one_connection (arg=0xaff2f00) at sql_connect.cc:1153
#17 0x00bd750b in start_thread () from /lib/libpthread.so.0
#18 0x00b18b2e in clone () from /lib/libc.so.6

How to repeat:
Simplified test case will hopefully follow shortly.

Suggested fix:
This looks like a corruption in the memory allocator.
[5 Mar 2008 13:22] Philip Stoev
Another stack trace produced under the same circumstances: deadlock + kill mysqld:

#0  0x00110402 in __kernel_vsyscall ()
#1  0x00bdc617 in pthread_kill () from /lib/libpthread.so.0
#2  0x0842ba24 in write_core (sig=6) at stacktrace.c:240
#3  0x082912a6 in handle_segfault (sig=6) at mysqld.cc:2313
#4  <signal handler called>
#5  0x00110402 in __kernel_vsyscall ()
#6  0x00a6e690 in raise () from /lib/libc.so.6
#7  0x00a6ff91 in abort () from /lib/libc.so.6
#8  0x085b4e4b in buf_block_align (ptr=0x8 <Address 0x8 out of bounds>) at ../../storage/innobase/include/buf0buf.ic:225
#9  0x085b6928 in buf_frame_free (frame=0x8 <Address 0x8 out of bounds>) at buf/buf0buf.c:980
#10 0x085edb13 in mem_heap_free_block_free (heap=0xb6fa1028) at mem/mem0mem.c:546
#11 0x085ecd0c in mem_heap_free_func (heap=0xb6fa1028, file_name=0x8868ab2 "row/row0mysql.c", line=742) at ../../storage/innobase/include/mem0mem.ic:478
#12 0x08605e47 in row_prebuilt_free (prebuilt=0xb6f9b268) at row/row0mysql.c:742
#13 0x085ab5d0 in ha_innobase::close (this=0x98d1e48) at handler/ha_innodb.cc:2463
#14 0x082f8fa5 in closefrm (table=0x98d1770, free_share=true) at table.cc:2042
#15 0x082e7a1a in intern_close_table (table=0x98d1770) at sql_base.cc:827
#16 0x082e7aba in free_cache_entry (table=0x98d1770) at sql_base.cc:849
#17 0x086c753a in hash_delete (hash=0x89f3620, record=0x98d1770 " \205\215\tH\036\215\t\b╟\215\txЛ═\t") at hash.c:529
#18 0x082ea1d2 in close_cached_tables (thd=0x0, if_wait_for_refresh=false, tables=0x0, have_lock=false) at sql_base.cc:903
#19 0x082ea961 in table_cache_free () at sql_base.cc:129
#20 0x0828fd95 in clean_up (print_message=true) at mysqld.cc:1212
#21 0x082908de in unireg_end () at mysqld.cc:1156
#22 0x08295657 in kill_server (sig_ptr=0x0) at mysqld.cc:1095
#23 0x08295677 in kill_server_thread (arg=0xb26db3b0) at mysqld.cc:1116
#24 0x00bd750b in start_thread () from /lib/libpthread.so.0
#25 0x00b18b2e in clone () from /lib/libc.so.6
[5 Mar 2008 14:32] Philip Stoev
Test case for bug 35080

Attachment: bug35080.zip (application/x-zip-compressed, text), 1.58 KiB.

[5 Mar 2008 14:35] Philip Stoev
To reproduce, please place the .txt files in mysql-test and the .test files in mysql-test/t . Then execute:

$ perl ./mysql-test-run.pl --stress --stress-init-file=bug35080_init.txt --stress-test-file=bug35080_run.txt --stress-test-duration=60000 --stress-threads=10 --skip-ndb --mysqld=--innodb

A crash will happen immediately, even before all the threads have been spawned.

May be related to bug #34590 and bug #34591, since all involve multi-table delete.
[7 Mar 2008 10:32] Philip Stoev
The bug is also repeatable with a debug build from the mysql-6.0 tree.
[7 Apr 2008 12:20] Heikki Tuuri
DROP TABLE is probably badly broken for MySQL/InnoDB in 6.0.

Calvin is the 6.0 release manager for InnoDB.
[9 Jul 2008 4:34] Calvin Sun
Philip,

Could you please try it again with DS-MRR and index condition pushdown off? You can do that by using:

set engine_condition_pushdown=off;
set optimizer_use_mrr='disable'; 

Likely this is also an optimizer bug, the same as bug #34590, bug #34591, and a couple of more.

Thanks,
Calvin
[9 Jul 2008 9:00] Philip Stoev
This bug goes away when using:

set engine_condition_pushdown=off;
set optimizer_use_mrr='disable'; 

Reassigning to Optimizer.
[8 Oct 2009 14:35] Guilhem Bichot
asked Philip for help because ./mtr doesn't accept --stress
[13 Oct 2009 15:01] Guilhem Bichot
Assigning to Philip for feedback regarding mtr --stress.
Philip, when you have provided feedback, please reassign to Olav.
[13 Oct 2009 16:32] Philip Stoev
Please either use 

MTR_VERSION=1 perl mysql-test-run.pl

or call mysql-stress-test.pl directly, again setting MTR_VERSION=1
[22 Oct 2009 12:28] Guilhem Bichot
Thanks Philip for the feedback; with MTR_VERSION=1 and a tree based on
revision-id:sp1r-hakank/hakan@lu0011.(none)-20080312214530-14286
(which is around the date where this bug was reported), MySQL crashes. Here is a testcase for mtr without Perl:

--source include/have_debug.inc
-- source include/have_innodb.inc

CREATE TABLE `inter1` (
  `t1_autoinc` int(11) NOT NULL AUTO_INCREMENT,
  `t1_uuid` varchar(36) DEFAULT NULL,
  `t2_uuid` char(36) DEFAULT NULL,
  `t1_blob` mediumtext,
  `filler` tinytext,
  PRIMARY KEY (`t1_autoinc`),
  KEY `t2_uuid` (`t2_uuid`),
  KEY `k1` (`t1_uuid`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1;

CREATE TABLE `inter2` (
  `t2_autoinc` int(11) NOT NULL AUTO_INCREMENT,
  `t1_uuid` varchar(36) DEFAULT NULL,
  `t2_uuid` char(36) DEFAULT NULL,
  `t2_date` datetime DEFAULT NULL,
  `filler` char(255) DEFAULT NULL,
  PRIMARY KEY (`t2_autoinc`),
  KEY `t1_uuid` (`t1_uuid`),
  KEY `k1` (`t2_uuid`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1;

/*!50001 CREATE ALGORITHM=UNDEFINED */
/*!50013 DEFINER=`root`@`localhost` SQL SECURITY DEFINER */
/*!50001 VIEW `view1` AS select `inter1`.`t1_autoinc` AS `t1_autoinc`,`inter1`.`t1_uuid` AS `t1_uuid`,`inter1`.`t2_uuid` AS `t2_uuid`,`inter1`.`t1_blob` AS `t1_blob` from `inter1` where (isnull(`inter1`.`t1_uuid`) or (`inter1`.`t1_uuid` like '%-%')) */;

/*!50001 CREATE ALGORITHM=UNDEFINED */
/*!50013 DEFINER=`root`@`localhost` SQL SECURITY DEFINER */
/*!50001 VIEW `view2` AS select `inter2`.`t2_autoinc` AS `t2_autoinc`,`inter2`.`t1_uuid` AS `t1_uuid`,`inter2`.`t2_uuid` AS `t2_uuid`,`inter2`.`t2_date` AS `t2_date` from `inter2` where (isnull(`inter2`.`t1_uuid`) or (length(`inter2`.`t1_uuid`) = 36)) */;

delimiter |;

CREATE DEFINER=`root`@`localhost` PROCEDURE `delete_multi`(IN uuid CHAR(36))
BEGIN
DELETE view1, view2 FROM view1 INNER JOIN view2
ON view1.t1_uuid = view2.t1_uuid
WHERE view1.t1_uuid = @uuid;
END |

delimiter ;|

SET @uuid = UUID();
START TRANSACTION;
INSERT INTO view1 (t1_uuid) VALUES (@uuid);
SELECT t1_autoinc FROM view1 WHERE t1_uuid = @uuid INTO @t1_autoinc;
INSERT INTO view2 (t1_uuid, t2_date) VALUES (@uuid, '2009-09-09');

set session engine_condition_pushdown=on;
# crash requires InnoDB ICP
set session debug="+d,optimizer_innodb_icp";
CALL delete_multi(@uuid);

drop procedure delete_multi;
drop table inter1,inter2;
drop view view1,view2;

This testcase crashes today's MySQL as well, alas:
#2  0x00000000006f6ad6 in handle_segfault (sig=11) at mysqld.cc:2754
#3  <signal handler called>
#4  0x00007f90cdd6440c in memcpy () from /lib/libc.so.6
#5  0x0000000000a27cfc in row_sel_field_store_in_mysql_format (dest=0x3101712 "e-bf06-11de-bf5d-00188bacc218\200", templ=0x3126240, 
    data=0x7f90cd518086 "e-bf06-11de-bf5d-00188bacc218\200", len=18446744073709551613) at row/row0sel.c:2567
#6  0x0000000000a27fa9 in row_sel_store_mysql_rec (mysql_rec=0x31016e8 "�812c", prebuilt=0x31120a0, rec=0x7f90cd51807f "49a6130e-bf06-11de-bf5d-00188bacc218\200", offsets=0x414cbd80, 
    start_field_no=0, end_field_no=5) at row/row0sel.c:2672
#7  0x0000000000a2a4bb in row_search_for_mysql (buf=0x31016e8 "�812c", mode=2, prebuilt=0x31120a0, match_mode=1, direction=0) at row/row0sel.c:4154
#8  0x00000000009be391 in ha_innobase::index_read (this=0x3101418, buf=0x31016e8 "�812c", key_ptr=0x3140568 "", key_len=39, find_flag=HA_READ_KEY_EXACT) at handler/ha_innodb.cc:4515
#9  0x00000000008696ec in handler::index_read_map (this=0x3101418, buf=0x31016e8 "�812c", key=0x3140568 "", keypart_map=1, find_flag=HA_READ_KEY_EXACT) at ../../sql/handler.h:1796
#10 0x0000000000786ef4 in join_read_always_key (tab=0x3140ac8) at sql_select.cc:16969
#11 0x0000000000789f6d in sub_select (join=0x31372b8, join_tab=0x3140ac8, end_of_records=false) at sql_select.cc:16284
#12 0x0000000000789ce2 in evaluate_join_record (join=0x31372b8, join_tab=0x3140828, error=0) at sql_select.cc:16554
#13 0x0000000000789fbd in sub_select (join=0x31372b8, join_tab=0x3140828, end_of_records=false) at sql_select.cc:16289
#14 0x000000000079802e in do_select (join=0x31372b8, fields=0x311c158, table=0x0, procedure=0x0) at sql_select.cc:15847
#15 0x00000000007b2821 in JOIN::exec (this=0x31372b8) at sql_select.cc:2906
#16 0x00000000007acf5c in mysql_select (thd=0x7f90c817d840, rref_pointer_array=0x311c260, tables=0x3128538, wild_num=0, fields=@0x311c158, conds=0x3125ee8, og_num=0, order=0x0, 
    group=0x0, having=0x0, proc_param=0x0, select_options=3490991744, result=0x312f948, unit=0x311b9a8, select_lex=0x311c048) at sql_select.cc:3097

We see from the test that it depends on InnoDB's Index Condition Pushdown. MRR is not involved.
[22 Oct 2009 12:37] Philip Stoev
Note that the original backtrace provided with the bug is different from the one obtained by Guilhem . So please use both test cases when verifying that this is fixed.
[24 Oct 2009 13:01] Guilhem Bichot
Hello Philip. Actually, when I used a tree of around the date when this bug was reported, with your exact testcase (stress test), I didn't get your stack trace, but the same stack trace as my reduced single-thread mtr testcase.
[12 Nov 2009 14:46] Olav Sandstå
I am not able to reproduce the crash using the initial test case for mysql-stress-test with ICP support enabled in InnoDB. Using the MTR test case provided by Guilhem still produces the crash.
[13 Nov 2009 9:17] Olav Sandstå
Running the MTR test case with valgrind shows that this bug contains the memory corruptions from both:

Bug#43360:

==1014== Invalid write of size 8
==1014==    at 0x8F020C: build_template(row_prebuilt_struct*, THD*, TABLE*, ha_innobase*, unsigned) (ha_innodb.cc:3437)
==1014==    by 0x8F3323: ha_innobase::change_active_index(unsigned) (ha_innodb.cc:4637)
==1014==    by 0x8F3492: ha_innobase::index_init(unsigned, bool) (ha_innodb.cc:4309)
==1014==    by 0x5812B3: handler::ha_index_init(unsigned, bool) (handler.h:1559)
==1014==    by 0x702FD7: join_read_always_key(st_join_table*) (sql_select.cc:16982)
==1014==    by 0x70653C: sub_select(JOIN*, st_join_table*, bool) (sql_select.cc:16311)
==1014==    by 0x7062BB: evaluate_join_record(JOIN*, st_join_table*, int) (sql_select.cc:16581)
==1014==    by 0x70658C: sub_select(JOIN*, st_join_table*, bool) (sql_select.cc:16316)
==1014==    by 0x71421A: do_select(JOIN*, List<Item>*, TABLE*, Procedure*) (sql_select.cc:15874)
==1014==    by 0x731B69: JOIN::exec() (sql_select.cc:2929)
==1014==    by 0x72C183: mysql_select(THD*, Item***, TABLE_LIST*, unsigned, List<Item>&, Item*, unsigned, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*) (sql_select.cc:3120)
==1014==    by 0x68AC9E: mysql_execute_command(THD*) (sql_parse.cc:3427)==1014==    by 0x87EB10: sp_instr_stmt::exec_core(THD*, unsigned*) (sp_head.cc:2923)
==1014==    by 0x87F49C: sp_lex_keeper::reset_lex_and_exec_core(THD*, unsigned*, bool, sp_instr*) (sp_head.cc:2746)
==1014==    by 0x87FBC1: sp_instr_stmt::execute(THD*, unsigned*) (sp_head.cc:2861)
==1014==    by 0x881E94: sp_head::execute(THD*) (sp_head.cc:1243)

as well as Bug#41996:

==5963== Thread 12:
==5963== Conditional jump or move depends on uninitialised value(s)
==5963==    at 0x95CD2D: row_sel_store_mysql_rec (row0sel.c:2614)
==5963==    by 0x95F3AC: row_search_for_mysql (row0sel.c:4154)
==5963==    by 0x8F36BE: ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned, ha_rkey_function) (ha_innodb.cc:4515)
==5963==    by 0x7E567F: handler::index_read_map(unsigned char*, unsigned char const*, unsigned long, ha_rkey_function) (handler.h:1796)
==5963==    by 0x703121: join_read_always_key(st_join_table*) (sql_select.cc:16996)
==5963==    by 0x70653C: sub_select(JOIN*, st_join_table*, bool) (sql_select.cc:16311)
==5963==    by 0x7062BB: evaluate_join_record(JOIN*, st_join_table*, int) (sql_select.cc:16581)
==5963==    by 0x70658C: sub_select(JOIN*, st_join_table*, bool) (sql_select.cc:16316)
==5963==    by 0x71421A: do_select(JOIN*, List<Item>*, TABLE*, Procedure*) (sql_select.cc:15874)
==5963==    by 0x731B69: JOIN::exec() (sql_select.cc:2929)
==5963==    by 0x72C183: mysql_select(THD*, Item***, TABLE_LIST*, unsigned, List<Item>&, Item*, unsigned, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*) (sql_select.cc:3120)
==5963==    by 0x68AC9E: mysql_execute_command(THD*) (sql_parse.cc:3427)==5963==    by 0x87EB10: sp_instr_stmt::exec_core(THD*, unsigned*) (sp_head.cc:2923)
==5963==    by 0x87F49C: sp_lex_keeper::reset_lex_and_exec_core(THD*, unsigned*, bool, sp_instr*) (sp_head.cc:2746)
==5963==    by 0x87FBC1: sp_instr_stmt::execute(THD*, unsigned*) (sp_head.cc:2861)
==5963==    by 0x881E94: sp_head::execute(THD*) (sp_head.cc:1243)
==5963==

Thus, this is likely a duplicate of Bug#43360 and Bug#41996. 

I am leaving the bug report open until these two bugs have been fixed in order to verify that these also solves this crash.
[19 Jan 2010 12:43] Olav Sandstå
This bug is a duplicate of Bug#43360 and/or Bug#36981. I have verified that this crash does no longer occur after applying the fixes for these two bugs.

Test case for this bug is committed here:

  http://lists.mysql.com/commits/97367
[21 Jan 2010 10:59] Olav Sandstå
Patch with an updated version of the test case for this bug is committed:

http://lists.mysql.com/commits/97591
[3 Feb 2010 9:30] Olav Sandstå
Patch containing updated version of test case:

http://lists.mysql.com/commits/99022
[26 Feb 2010 9:50] Olav Sandstå
Patch containing test case pushed to mysql-6.0-codebase-bugfixing with revision-id: olav@sun.com-20100226091930-qxvakxmcp6463t5w .
[26 Feb 2010 9:57] Olav Sandstå
Closing this as duplicate of Bug#36981.
[6 Mar 2010 10:29] Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20100306102742-yw9zzgw9ac5r65m5) (version source revid:bar@mysql.com-20100305074327-h09o5lw290s04lcf) (merge vers: 6.0.14-alpha) (pib:16)
[16 Aug 2010 6:40] Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100816062819-bluwgdq8q4xysmlg) (version source revid:alik@sun.com-20100816062612-enatdwnv809iw3s9) (pib:20)
[13 Nov 2010 16:20] Bugs System
Pushed into mysql-trunk 5.6.99-m5 (revid:alexander.nozdrin@oracle.com-20101113155825-czmva9kg4n31anmu) (version source revid:vasil.dimov@oracle.com-20100629074804-359l9m9gniauxr94) (merge vers: 5.6.99-m4) (pib:21)