MySQL Bugs: #48246: assert in close_thread

Bug #48246	assert in close_thread_table
Submitted:	22 Oct 2009 20:48	Modified:	28 Apr 2010 2:01
Reporter:	Matthias Leich	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Locking	Severity:	S2 (Serious)
Version:	mysql-6.0-codebase-bugfixing	OS:	Any
Assigned to:	Jon Olav Hauglid	CPU Architecture:	Any
Tags:	regression

Description:
The assert happens in sql_base.cc:1525 :
     DBUG_ASSERT(!table->file || table->file->inited == handler::NONE);

mysql-6.0-codebase-bugfixing
revno: 3654 2009-10-15
-------------------------------------------
Thread 1 (process 31119):
#0  0x00007f5225c5d1f6 in pthread_kill () from /lib/libpthread.so.0
#1  0x0000000000b8f05c in my_write_core (sig=6) at stacktrace.c:309
#2  0x00000000006f6f17 in handle_segfault (sig=6) at mysqld.cc:2754
#3  <signal handler called>
#4  0x00007f5224b11fb5 in raise () from /lib/libc.so.6
#5  0x00007f5224b13bc3 in abort () from /lib/libc.so.6
#6  0x00007f5224b0af09 in __assert_fail () from /lib/libc.so.6
#7  0x0000000000764377 in close_thread_table (thd=0x3141f78, table_ptr=0x3142008) at sql_base.cc:1525
#8  0x0000000000764b64 in close_open_tables (thd=0x3141f78) at sql_base.cc:1257
#9  0x0000000000764f6a in close_thread_tables (thd=0x3141f78) at sql_base.cc:1500
#10 0x0000000000907508 in sp_lex_keeper::reset_lex_and_exec_core (this=0x36ad238, thd=0x3141f78, nextp=0x7f5219306338, open_tables=false, instr=0x36ad1f8) at sp_head.cc:2754
#11 0x000000000090da7e in sp_instr_stmt::execute (this=0x36ad1f8, thd=0x3141f78, nextp=0x7f5219306338) at sp_head.cc:2859
#12 0x00000000009098b4 in sp_head::execute (this=0x3739c10, thd=0x3141f78) at sp_head.cc:1243
#13 0x000000000090ae41 in sp_head::execute_trigger (this=0x3739c10, thd=0x3141f78, db_name=0x7f521408a6e8, table_name=0x7f521408a6f8, grant_info=0x34d9b68) at sp_head.cc:1552
#14 0x0000000000919e33 in Table_triggers_list::process_triggers (this=0x34d99f0, thd=0x3141f78, event=TRG_EVENT_DELETE, time_type=TRG_ACTION_AFTER, old_row_is_record1=false) at sql_trigger.cc:2016
#15 0x00000000007dbb95 in mysql_delete (thd=0x3141f78, table_list=0x7f5214154920, conds=0x7f5214155030, order=0x7f5214153e80, limit=1, options=4194304, reset_auto_increment=false) at sql_delete.cc:323
#16 0x000000000070d8c0 in mysql_execute_command (thd=0x3141f78) at sql_parse.cc:3384
#17 0x00000000007c7ba6 in Prepared_statement::execute (this=0x7f5214075c88, expanded_query=0x7f52193088c0, open_cursor=false) at sql_prepare.cc:3766
#18 0x00000000007cbeda in Prepared_statement::execute_loop (this=0x7f5214075c88, expanded_query=0x7f52193088c0, open_cursor=false, packet=0x0, packet_end=0x0) at sql_prepare.cc:3398
#19 0x00000000007cc172 in mysql_sql_stmt_execute (thd=0x3141f78) at sql_prepare.cc:2571
#20 0x000000000070a545 in mysql_execute_command (thd=0x3141f78) at sql_parse.cc:2131
#21 0x0000000000712b87 in mysql_parse (thd=0x3141f78, inBuf=0x31afe00 "EXECUTE st1", length=11, found_semicolon=0x7f521930a900) at sql_parse.cc:5991
#22 0x00000000007137d2 in dispatch_command (command=COM_QUERY, thd=0x3141f78, packet=0x31a7ee9 " EXECUTE st1 ", packet_length=13) at sql_parse.cc:1074
#23 0x0000000000714d3d in do_command (thd=0x3141f78) at sql_parse.cc:756
#24 0x0000000000701784 in handle_one_connection (arg=0x3141f78) at sql_connect.cc:1164
#25 0x00007f5225c583ba in start_thread () from /lib/libpthread.so.0
#26 0x00007f5224bc4fcd in clone () from /lib/libc.so.6
#27 0x0000000000000000 in ?? ()

The assert was found when running a RQG test with 30 threads
on an derivate of the grammar WL5004_sql.yy.

I will come up with a simplified testcase soon.

Some hint:
----------
The fix for
Bug#46791 Assertion failed:(table->key_read==0),
          function unknown function,file sql_base.cc
is within my source tree

How to repeat:
See above

Any attempt to replay this bug like grammar simplification
was not successful. Therefor I set this bug to
"Can't repeat" but will restart attempts if I have the time.

grammar for bug 48246

Attachment: bug48246.yy (application/octet-stream, text), 849 bytes.

To reproduce with the RQG

$ perl runall.pl \
  --basedir=/build/bzr/6.0-codebase-bugfixing \
  --grammar=conf/bug48246.yy \
  --gendata=conf/metadata_locking.zz

Crash should happen within 60 seconds. 5.0 and mysql-next-mr are not affected, so this is a 6.0 regression.

conf/metadata_locking.zz has been renamed conf/metadata_stability.zz

Not repeatable with the above grammar with the (in progress) patch for Bug #30977.

Still repeatable with 6.0-codebase-bugfixing.

new grammar for bug 48246

Attachment: bug48246-2.yy (application/octet-stream, text), 861 bytes.

Using the new grammar, RQG instead causes an assert in:
  DBUG_ASSERT(table->key_read == 0);

Updated backtrace:

#6  0x00007f7ae7f1d481 in *__GI___assert_fail (assertion=0xd8400b "table->key_read == 0", file=<value optimized out>, line=1528, function=0xd86760 "bool close_thread_table(THD*, TABLE**)") at assert.c:81
#7  0x0000000000762dec in close_thread_table (thd=0x2dcff50, table_ptr=0x2dcffe0) at sql_base.cc:1528
#8  0x000000000076267b in close_open_tables (thd=0x2dcff50) at sql_base.cc:1261
#9  0x0000000000762d30 in close_thread_tables (thd=0x2dcff50) at sql_base.cc:1504
#10 0x00000000009130c4 in sp_lex_keeper::reset_lex_and_exec_core (this=0x2e582d0, thd=0x2dcff50, nextp=0x7f7adc842d88, open_tables=true, instr=0x2e58288) at sp_head.cc:2756
#11 0x0000000000914134 in sp_instr_freturn::execute (this=0x2e58288, thd=0x2dcff50, nextp=0x7f7adc842d88) at sp_head.cc:3205
#12 0x000000000090f458 in sp_head::execute (this=0x2e56268, thd=0x2dcff50) at sp_head.cc:1245
#13 0x000000000091080d in sp_head::execute_function (this=0x2e56268, thd=0x2dcff50, argp=0x2e3de28, argcount=1, return_value_fld=0x2eebb38) at sp_head.cc:1770
#14 0x0000000000658907 in Item_func_sp::execute_impl (this=0x2e3dda8, thd=0x2dcff50) at item_func.cc:6143
#15 0x00000000006586b2 in Item_func_sp::execute (this=0x2e3dda8) at item_func.cc:6072
#16 0x000000000065b3f6 in Item_func_sp::val_int (this=0x2e3dda8) at item_func.h:1646
#17 0x0000000000623632 in Item::save_in_field (this=0x2e3dda8, field=0x2eec1b8, no_conversions=true) at item.cc:5370
#18 0x000000000062ff40 in Item_result_field::save_in_result_field (this=0x2e3dda8, no_conversions=true) at item.h:2229
#19 0x00000000007b5132 in copy_funcs (func_ptr=0x2ef17f8) at sql_select.cc:21102
#20 0x000000000063699c in Aggregator_distinct::add (this=0x2eeb228) at item_sum.cc:974
#21 0x0000000000640bd1 in Item_sum::aggregator_add (this=0x2e44218) at item_sum.h:499
#22 0x0000000000640a2e in Item_sum::reset (this=0x2e44218) at item_sum.h:396
#23 0x00000000007b5066 in init_sum_functions (func_ptr=0x2eebbe8, end_ptr=0x2eebbf0) at sql_select.cc:21072
#24 0x00000000007acc6a in end_send_group (join=0x2ef4088, join_tab=0x2eea8b8,  end_of_records=false) at sql_select.cc:17709
#25 0x00000000007aa699 in evaluate_join_record (join=0x2ef4088, join_tab=0x2eea608, error=0) at sql_select.cc:16779
#26 0x00000000007a9cb2 in sub_select (join=0x2ef4088, join_tab=0x2eea608, end_of_records=false) at sql_select.cc:16497
#27 0x00000000007a919d in do_select (join=0x2ef4088, fields=0x2ef9d28, table=0x0, procedure=0x0) at sql_select.cc:16041
#28 0x00000000007899bf in JOIN::exec (this=0x2ef4088) at sql_select.cc:2949
#29 0x000000000078a068 in mysql_select (thd=0x2dcff50, rref_pointer_array=0x2e3c9d0, tables=0x2e3e0c8, wild_num=0, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147749376, result=0x2e3df18, unit=0x2e3c118,  select_lex=0x2e3c7b8) at sql_select.cc:3140
#30 0x0000000000781423 in handle_select (thd=0x2dcff50, lex=0x2e3c078, result=0x2e3df18, setup_tables_done_option=0) at sql_select.cc:308
#31 0x0000000000716b7c in execute_sqlcom_select (thd=0x2dcff50, all_tables=0x2e3e0c8) at sql_parse.cc:4961
#32 0x000000000070e45a in mysql_execute_command (thd=0x2dcff50) at sql_parse.cc:2156
#33 0x0000000000913676 in sp_instr_stmt::exec_core (this=0x2e3e6c8, thd=0x2dcff50, nextp=0x7f7adc845978) at sp_head.cc:2925
#34 0x000000000091305b in sp_lex_keeper::reset_lex_and_exec_core (this=0x2e3e710, thd=0x2dcff50, nextp=0x7f7adc845978, open_tables=false, instr=0x2e3e6c8) at sp_head.cc:2748
#35 0x0000000000913449 in sp_instr_stmt::execute (this=0x2e3e6c8, thd=0x2dcff50, nextp=0x7f7adc845978) at sp_head.cc:2863
#36 0x000000000090f458 in sp_head::execute (this=0x2e43738, thd=0x2dcff50) at sp_head.cc:1245
#37 0x0000000000911205 in sp_head::execute_procedure (this=0x2e43738, thd=0x2dcff50, args=0x2dd24f0) at sp_head.cc:1985
#38 0x0000000000714d59 in mysql_execute_command (thd=0x2dcff50) at sql_parse.cc:4419
#39 0x0000000000718e4a in mysql_parse (thd=0x2dcff50, inBuf=0x2ed32b8 "CALL /* RESULTSET_SAME_DATA_IN_EVERY_ROW */ proc_2 ( @inout1 )", length=62, found_semicolon=0x7f7adc8478c8) at sql_parse.cc:5975

(gdb) p table->key_read
$9 = 1 '\001'
(gdb) p table->file->inited
$10 = handler::INDEX
(gdb) p *thd->stmt_da
$8 = {is_sent = false, can_overwrite_status = false, m_message = "\000UNCTION func_1 already exists\000'table_3' for update in FROM clause", '\000' <repeats 444 times>, "Z", m_sql_errno = 1304, m_sqlstate = "42000", m_server_status = 34, m_affected_rows = 0, m_last_insert_id = 0, m_statement_warn_count = 0, m_status = Diagnostics_area::DA_EMPTY}

From frame 36:
proc_2 = BEGIN SELECT COUNT(DISTINCT func_1 ( `col_int_key` ) ) INTO inout1 FROM  table_1 ; END

From frame 12:
func_1 = CREATE FUNCTION `func_1`(in1 INTEGER) RETURNS int(11)\nRETURN 5

I have been able to reproduce it using --threads=2, but not with --threads=1.
Bug still only present in 6.0, not in 5.1-bugteam or next-mr-bugfixing.

Non-deterministic MTR test case:

CREATE TABLE t1 (a INTEGER, KEY (a));
CREATE FUNCTION f1(b INTEGER) RETURNS INTEGER RETURN 1;
CREATE PROCEDURE p1() SELECT COUNT(f1(a)) FROM t1;

INSERT INTO t1 VALUES(1), (2);

connect (con2,localhost,root);

let $try=100;

while ($try)
{
        connection con2;
        --send CREATE TABLE t1 (a INTEGER)

        connection default;
        CALL p1();

        connection con2;
        --error ER_TABLE_EXISTS_ERROR
        --reap

        dec $try;
}

connection default;
disconnect con2;
DROP PROCEDURE p1;
DROP FUNCTION f1;
DROP TABLE t1;

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/93126

3761 Jon Olav Hauglid	2009-12-08
      Bug #48246 assert in close_thread_table
      
      This assert would occur if a stored procedure which already had its prelocking
      list of tables built, had to back off and retry to open its tables due to a
      conflicting MDL lock.
      
      During back-off, the list of prelocked tables is thrown away so it can be
      recomputed. This is needed since it is possible that one of the tables that
      determined the prelocking list, now has changed.
      
      The problem was that the variable that indicates if the prelocking list exists,
      was not reset. This caused the open tables code to believe that the prelocking
      list still existed. Since the prelocking list was empty, prelocking mode was not
      entered as it should have been. This caused an assert when a function called
      from the stored procedure tried to close its tables.
      
      Test case added to mdl_sync.test.

Will be queued along with 30977, there is a dependency.

Queued in next-4284.

Bug#48155 marked as a duplicate of this bug.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/98168

3055 Jon Olav Hauglid	2010-01-26
      Additional test coverage for
      Bug#30977 Concurrent statement using stored function and
                DROP FUNCTION breaks SBR
      Bug#48246 assert in close_thread_table

Pushed into 6.0.14-alpha (revid:alik@sun.com-20100216101445-2ofzkh48aq2e0e8o) (version source revid:kostja@sun.com-20091230202224-tmxmnhhvlecoej8w) (merge vers: 6.0.14-alpha) (pib:16)

Pushed into mysql-next-mr (revid:alik@sun.com-20100216101208-33qkfwdr0tep3pf2) (version source revid:kostja@sun.com-20091229121905-q27v9932ho9as2ws) (pib:16)

Not present in any released version. No changelog entry needed.

Pushed into 5.5.3-m3 (revid:alik@sun.com-20100306103849-hha31z2enhh7jwt3) (version source revid:vvaintroub@mysql.com-20100216221947-luyhph0txl2c5tc8) (merge vers: 5.5.99-m3) (pib:16)

No changelog entry needed.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/106003

3004 Jon Olav Hauglid	2010-04-19
      Additional test coverage for
      Bug#30977 Concurrent statement using stored function and
                DROP FUNCTION breaks SBR
      Bug#48246 assert in close_thread_table

Patch containing extra test coverage pushed to mysql-trunk-runtime (Ver 5.5.4-m3).
Since the patch contains no code changes, I'm leaving the bug as Closed.

Pushed into 6.0.14-alpha (revid:alik@sun.com-20100427094135-5s49ecp3ckson6e2) (version source revid:alik@sun.com-20100427093843-uekr85qkd7orx12t) (merge vers: 6.0.14-alpha) (pib:16)

Pushed into 5.5.5-m3 (revid:alik@sun.com-20100427093804-a2k3rrjpwu5jegu8) (version source revid:alik@sun.com-20100427093804-a2k3rrjpwu5jegu8) (merge vers: 5.5.5-m3) (pib:16)

Pushed into mysql-next-mr (revid:alik@sun.com-20100427094036-38frbg3famdlvjup) (version source revid:alik@sun.com-20100427093825-92wc8b22d4yg34ju) (pib:16)

No changelog entry needed.