Bug #55986 Assertion `inited==INDEX' in handler::ha_index_end() on INSERT..SELECT..(SELECT)
Submitted: 15 Aug 2010 2:51 Modified: 6 Jun 2011 7:12
Reporter: Elena Stepanova Email Updates:
Status: Duplicate Impact on me:
None 
Category:MySQL Server: Optimizer Severity:S1 (Critical)
Version:5.6.99-m5-debug, 5.6.2-debug OS:Any
Assigned to: Roy Lyseng CPU Architecture:Any
Tags: regression

[15 Aug 2010 2:51] Elena Stepanova
Description:
Reproducible on current next-mr-bugfixing-debug.
Could not reproduce on 5.5 or 5.6 (trunk).

(Note: The test case and back trace contain REPLACE, but this is for convenience (scenario simplification); same happens with INSERT.)

mysqld: mysql-5.6.99-m5/sql/handler.h:1534: int handler::ha_index_end(): Assertion `inited==INDEX' failed

#6  0x00002b7320313286 in __assert_fail () from /lib64/libc.so.6
#7  0x0000000000588fd6 in handler::ha_index_end (this=0x2aaab4706780)
    at mysql-5.6.99-m5/sql/handler.h:1534
#8  0x00000000007b8a13 in subselect_uniquesubquery_engine::cleanup (this=0x1fbe088)
    at mysql-5.6.99-m5/sql/item_subselect.cc:2098
#9  0x00000000007b8ef1 in Item_subselect::cleanup (this=0x1fbc420)
    at mysql-5.6.99-m5/sql/item_subselect.cc:123
#10 0x00000000007b9019 in Item_in_subselect::cleanup (this=0x1fbc420)
    at mysql-5.6.99-m5/sql/item_subselect.cc:169
#11 0x00000000005b57ce in Item::delete_self (this=0x1fbc420) at mysql-5.6.99-m5/sql/item.h:1163
#12 0x00000000005acb2d in Query_arena::free_items (this=0x1f94a38)
    at mysql-5.6.99-m5/sql/sql_class.cc:2530
#13 0x00000000005acbee in THD::cleanup_after_query (this=0x1f94a20)
    at mysql-5.6.99-m5/sql/sql_class.cc:1318
#14 0x00000000005e6c02 in mysql_parse (thd=0x1f94a20,
    rawbuf=0x1f9f7d0 "REPLACE test.t1_tmp SELECT 1, `col_int` FROM `table1_innodb_int_autoinc` WHERE `pk` IN ( SELECT `pk` FROM `table1_innodb_int_autoinc` )", length=135, parser_state=0x47110a10) at mysql-5.6.99-m5/sql/sql_parse.cc:5846
#15 0x00000000005e7733 in dispatch_command (command=COM_QUERY, thd=0x1f94a20,
    packet=0x1f977a1 "REPLACE test.t1_tmp SELECT 1, `col_int` FROM `table1_innodb_int_autoinc` WHERE `pk` IN ( SELECT `pk` FROM `table1_innodb_int_autoinc` )", packet_length=135) at mysql-5.6.99-m5/sql/sql_parse.cc:1128
#16 0x00000000005e8b9e in do_command (thd=0x1f94a20) at mysql-5.6.99-m5/sql/sql_parse.cc:800
#17 0x00000000006b9c12 in do_handle_one_connection (thd_arg=0x1f94a20)
    at mysql-5.6.99-m5/sql/sql_connect.cc:1191
#18 0x00000000006b9cdb in handle_one_connection (arg=0x1f94a20)
    at mysql-5.6.99-m5/sql/sql_connect.cc:1130
#19 0x00002b731fd3b143 in start_thread () from /lib64/libpthread.so.0
#20 0x00002b73203aa8cd in clone () from /lib64/libc.so.6

Some pointers may be invalid and cause the dump to abort...
thd->query at 0x1f9f7d0 = REPLACE test.t1_tmp SELECT 1, `col_int` FROM `table1_innodb_int_autoinc` WHERE `pk` IN ( SELECT `pk` FROM `table1_innodb_int_autoinc` )
thd->thread_id=5
thd->killed=NOT_KILLED

How to repeat:
# Theoretically 2 threads are enough to reproduce the issue, 
# the parameter value has been increased to make it happen faster.
# Normally with 10 threads it takes less than a minute

perl ./runall-new.pl \
--basedir=<path to mysql-next-mr-bugfixing-debug> \
--vardir=<vardir> \
--grammar=./my_grammar.yy \
--gendata=my_table.zz \
--queries=10000 \
--threads=10

#---------
# my_grammar.yy

query_init:
CREATE TEMPORARY TABLE test.t1_tmp LIKE _table;

query:
insert_tmp | update ;

insert_tmp:
REPLACE test.t1_tmp SELECT 1, _field_no_pk FROM _table WHERE `pk` IN ( SELECT `pk` FROM _table ) ;

update:
UPDATE _table target SET _field_no_pk = _int ;

#---------
my_table.zz

$tables = {
        rows => [1],
        engines => ['InnoDB'],
        pk => [ 'int auto_increment' ]
};

$fields = {
        types => [ 'int' ],
        indexes => [ undef ]
};

$data = {
        numbers => [ 'digit' ],
}

#---------
[4 Oct 2010 7:37] Roy Lyseng
The code that causes the regression was backported from the former 6.0 development branch at 2010-02-27. The backported code comes from WL#1110 - Subquery optimization: Materialization.

This is a genuine regression - there is no need to toggle any optimizer switch settings to provoke the error.
[31 Jan 2011 6:36] MySQL Verification Team
i appear to run into this bug alot on mysql-trunk when explaining selects with many views and joins and subqueries.  no testcase yet, but i've seen it in a single threaded test.

mysqld: ./sql/handler.h:1551: int handler::ha_index_end(): Assertion `inited==INDEX' failed.
110130 13:59:03 - mysqld got signal 6 ;

(gdb) bt
#0  __pthread_kill at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:63
#1 in my_write_core at ./mysys/stacktrace.c:423
#2 in handle_segfault at ./sql/mysqld.cc:2512
#3  <signal handler called>
#4  in ?? ()
#5  in handler::ha_index_end at ./sql/handler.h:1554
#6  in subselect_uniquesubquery_engine::cleanup at ./sql/item_subselect.cc:2138
#7  in Item_subselect::cleanup at ./sql/item_subselect.cc:123
#8  in Item_in_subselect::cleanup at ./sql/item_subselect.cc:155
#9  in Item::delete_self at ./sql/item.h:1171
#10 in Query_arena::free_items at ./sql/sql_class.cc:2674
#11 in THD::cleanup_after_query at ./sql/sql_class.cc:1452
#12 in mysql_parse at ./sql/sql_parse.cc:5565
#13 in dispatch_command at ./sql/sql_parse.cc:1078
#14 in do_command at ./sql/sql_parse.cc:815
#15 in do_handle_one_connection at ./sql/sql_connect.cc:748
#16 in handle_one_connection at ./sql/sql_connect.cc:684
#17 in start_thread at pthread_create.c:301
#18 in clone at ../sysdeps/unix/sysv/linux/x86_64/clone.S:115
(gdb) 

The explain for these particular queries all have index_subquery join types:
+--------------------+-------+----------------+-
| select_type        | table | type           |
+--------------------+-------+----------------+-
| PRIMARY            | t1_0  | ALL            |
| PRIMARY            | t69_4 | index          |
| PRIMARY            | t48_1 | index          |
| PRIMARY            | t50_3 | ALL            |
| DEPENDENT SUBQUERY | t95_2 | index_subquery |
+--------------------+-------+----------------+-
[31 Jan 2011 13:41] MySQL Verification Team
Roy, you might be right. I repeated this bug in a single thread alot easier after I ran set global table_open_cache=1.  In valgrind it looks like this:

Version: '5.6.2-m5-valgrind-max-debug'  socket: 'sock'  port: 3306  Source distribution
Thread 18:
Invalid read of size 8
at: subselect_uniquesubquery_engine::cleanup() (item_subselect.cc:2137)
by: Item_subselect::cleanup() (item_subselect.cc:123)
by: Item_in_subselect::cleanup() (item_subselect.cc:155)
by: Item::delete_self() (item.h:1171)
by: Query_arena::free_items() (sql_class.cc:2674)
by: THD::cleanup_after_query() (sql_class.cc:1452)
by: mysql_parse(THD*, char*, unsigned int, Parser_state*) (sql_parse.cc:5565)
by: dispatch_command(enum_server_command, THD*, char*, unsigned int) (sql_parse.cc:1078)
by: do_command(THD*) (sql_parse.cc:815)
by: do_handle_one_connection(THD*) (sql_connect.cc:748)
by: handle_one_connection (sql_connect.cc:684)
by: start_thread (pthread_create.c:301)
 Address 0x15b1ea68 is 8 bytes inside a block of size 2,240 free'd
at: free (vg_replace_malloc.c:325)
by: my_free (my_malloc.c:128)
by: free_cache_entry(TABLE*) (sql_base.cc:880)
by: close_thread_table(THD*, TABLE**) (sql_base.cc:1562)
by: close_open_tables(THD*) (sql_base.cc:1299)
by: close_thread_tables(THD*) (sql_base.cc:1506)
by: mysql_execute_command(THD*) (sql_parse.cc:4419)
by: mysql_parse(THD*, char*, unsigned int, Parser_state*) (sql_parse.cc:5550)
by: dispatch_command(enum_server_command, THD*, char*, unsigned int) (sql_parse.cc:1078)
by: do_command(THD*) (sql_parse.cc:815)
by: do_handle_one_connection(THD*) (sql_connect.cc:748)
by: handle_one_connection (sql_connect.cc:684)
by: start_thread (pthread_create.c:301)

0x00000000007eee87 in subselect_uniquesubquery_engine::cleanup (this=0x1a30f4e0) at /home/sbester/build/bzr/mysql-trunk/sql/item_subselect.cc:2137
2137      if (tab->table->file->inited)
(gdb) list
2132
2133    void subselect_uniquesubquery_engine::cleanup()
2134    {
2135      DBUG_ENTER("subselect_uniquesubquery_engine::cleanup");
2136      /* Tell handler we don't need the index anymore */
2137      if (tab->table->file->inited)
2138        tab->table->file->ha_index_end();
2139      DBUG_VOID_RETURN;
2140    }
2141
(gdb) p tab->table->file->inited
Cannot access memory at address 0x188
(gdb) p tab->table->file
$1 = (handler *) 0x0
(gdb) p tab->table
$2 = (TABLE *) 0x15b1ea60
[1 Mar 2011 16:40] Roy Lyseng
I just pushed a bug fix for bug#56080 (aka 11763382) into mysql-next-mr-backporting branch. Please investigate whether the fix also solves this problem.
[1 Apr 2011 23:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".
[2 May 2011 23:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".
[3 Jun 2011 23:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".