MySQL Bugs: #41038: Maria: assertion in free_block() when dropping open table (pushbuild2)

Bug #41038	Maria: assertion in free_block() when dropping open table (pushbuild2)
Submitted:	25 Nov 2008 22:49	Modified:	26 May 2010 17:50
Reporter:	Guilhem Bichot	Email Updates:
Status:	Unsupported	Impact on me:	None
Category:	MySQL Server: Maria storage engine	Severity:	S3 (Non-critical)
Version:	6.0-maria	OS:	Any
Assigned to:		CPU Architecture:	Any
Triage:	Triaged: D1 (Critical) / R1 (None/Negligible) / E2 (Low)

Description:
Assertion failed: block->wlocks == 0, file ma_pagecache.c, line 4100
#7 0xfeec023c in _assert () from /lib/libc.so.1 #8 0x008e0de0 in free_block (pagecache=0x1870168, block=0x52f3448)
    at ma_pagecache.c:4100
#9 0x008e22f0 in flush_pagecache_blocks_int (pagecache=0x1870168,
    file=0x5707bc8, type=FLUSH_IGNORE_CHANGED, filter=0, filter_arg=0x0)
    at ma_pagecache.c:4505
#10 0x008e2898 in flush_pagecache_blocks_with_filter (pagecache=0x1870168,
    file=0x5707bc8, type=FLUSH_IGNORE_CHANGED, filter=0, filter_arg=0x0)
    at ma_pagecache.c:4644
#11 0x008fd13c in _ma_flush_table_files (info=0x5707918,
    flush_data_or_index=3, flush_type_for_data=FLUSH_IGNORE_CHANGED, 
    flush_type_for_index=FLUSH_IGNORE_CHANGED) at ma_extra.c:590
#12 0x008fc5bc in maria_extra (info=0x5707918,
    function=HA_EXTRA_PREPARE_FOR_DROP, extra_arg=0x0) at ma_extra.c:334
#13 0x008ecb60 in ha_maria::extra (this=0x5782840,
    operation=HA_EXTRA_PREPARE_FOR_DROP) at ha_maria.cc:2125
#14 0x00312b14 in drop_open_table (thd=0x577fc30, table=0x5782178,
    db_name=0x579f6f0 "test", table_name=0x579f4c8 "z") at sql_base.cc:2106
#15 0x00382db4 in create_table_from_items (thd=0x577fc30,
    create_info=0xfd8710e0, create_table=0x579f4f0, alter_info=0xfd8715c8, 
    items=0x5781208, lock=0xfd870c74, hooks=0xfd870a58) at sql_insert.cc:3573
#16 0x003830a8 in select_create::prepare (this=0x579fe40, values=@0x5781208,
    u=0x5780ed0) at sql_insert.cc:3652
#17 0x00369ed8 in JOIN::prepare (this=0x579be18, rref_pointer_array=0x5781278,
    tables_init=0x579f9f8, wild_num=1, conds_init=0x0, og_num=0, 
    order_init=0x0, group_init=0x0, having_init=0x0, proc_param_init=0x0, 
    select_lex_arg=0x5781170, unit_arg=0x5780ed0) at sql_select.cc:790
#18 0x00375eac in mysql_select (thd=0x577fc30, rref_pointer_array=0x5781278,
    tables=0x579f9f8, wild_num=1, fields=@0x5781208, conds=0x0, og_num=0, 
    order=0x0, group=0x0, having=0x0, proc_param=0x0, 
    select_options=2416200192, result=0x579fe40, unit=0x5780ed0, 
    select_lex=0x5781170) at sql_select.cc:2995
#19 0x00376420 in handle_select (thd=0x577fc30, lex=0x5780e70,
    result=0x579fe40, setup_tables_done_option=0) at sql_select.cc:301
#20 0x002ba844 in mysql_execute_command (thd=0x577fc30) at sql_parse.cc:2566 #21 0x002c37fc in mysql_parse (thd=0x577fc30,
    inBuf=0x579f430 "CREATE TABLE z SELECT * FROM `h`", length=32, 
    found_semicolon=0xfd871dc8) at sql_parse.cc:5719

How to repeat:
don't know.

Suggested fix:
Note that the function drop_open_table() is mentioned in the trace, which Monty touched in August in monty@mysql.com-20080818222122-pd3rj6et36y9a2jz , where he added the extra() call which is in the trace too.
Given that this is about dropping an open table, *maybe* some other thread is still working with the table, has a page locked, and that's why free_block() asserts...

Monty's change is also in 5.1-maria

Sanja: looking at stack trace, it looks like the "CREATE TABLE z SELECT * FROM `h`" got an error early: it created the table, then failed inside some locking code:
  /*
    mysql_lock_tables() below should never fail with request to reopen table
    since it won't wait for the table lock (we have exclusive metadata lock on
    the table) and thus can't get aborted and since it ignores other threads
    setting THD::some_tables_deleted thanks to MYSQL_LOCK_IGNORE_FLUSH.
  */
  if (! ((*lock)= mysql_lock_tables(thd, &table, 1,
                                    MYSQL_LOCK_IGNORE_FLUSH, &not_used)) ||
        hooks->postlock(&table, 1))
  {
    if (*lock)
    {
      mysql_unlock_tables(thd, *lock);
      *lock= 0;
    }

    if (!create_info->table_existed)
>      drop_open_table(thd, table, create_table->db, create_table->table_name);
    DBUG_RETURN(0);
  }
(from create_table_from_items()).
As the table is brand new, shouldn't the pagecache flush find no page at all?
Or is the table accessible to other threads between being created and opened (this used to be an old bug, but has been fixed I believe).

Progress report:

Tried to repeat the bug by patching the code lock code in create_table_from_items() to always fail in different manners

Found one possible bug in mysqld which casues an assert if my_error() was not called in postlock(). However was not abloe to get Maria to crash.

What is strange is that if we fail in create_table_from_items(), there should not be any blocks in the page cache for the failed table.  I verified this by checking the debug trace file.

Now trying to repeat this bug by adding an assert in the failed code and running the pushbuild2 test locally.

Suggestion to fix ok with me

Probably still exists, because I see it occured on Feb 16.

http://loki41.norway.sun.com/~bteam/pb2/web_loki41.py?action=archive_download&archive_id=3...
push: serg@mysql.com-2... 2009-02-16 22:23:22 
machine: sol10 sparc32 sysqa
Since then, there have been 4 pushes without this failure (but with others).
We didn't change anything pagecache-related in those 4 pushes (but there have been merges from 6.0-main, which could have imported a change about dropping tables in the server).
Impossible to know if it's fixed or hidden, as the test is still red.
So we should keep this open until the test gets green for a while.

Assertion failed: block->rlocks == 0, file ma_pagecache.c, line 4110
#7 0xfeec023c in _assert () from /lib/libc.so.1 #8 0x00908364 in free_block (pagecache=0x18c70d0, block=0x4f830b8)
    at ma_pagecache.c:4110
#9 0x00909840 in flush_pagecache_blocks_int (pagecache=0x18c70d0,
    file=0x7ebbb58, type=FLUSH_IGNORE_CHANGED, filter=0, filter_arg=0x0)
    at ma_pagecache.c:4514
#10 0x00909de8 in flush_pagecache_blocks_with_filter (pagecache=0x18c70d0,
    file=0x7ebbb58, type=FLUSH_IGNORE_CHANGED, filter=0, filter_arg=0x0)
    at ma_pagecache.c:4653
#11 0x0092de3c in _ma_flush_table_files (info=0x7ebb8a0,
    flush_data_or_index=3, flush_type_for_data=FLUSH_IGNORE_CHANGED, 
    flush_type_for_index=FLUSH_IGNORE_CHANGED) at ma_extra.c:639
#12 0x0092d178 in maria_extra (info=0x7ebb8a0,
    function=HA_EXTRA_PREPARE_FOR_DROP, extra_arg=0x0) at ma_extra.c:355
#13 0x00914340 in ha_maria::extra (this=0x81951e8,
    operation=HA_EXTRA_PREPARE_FOR_DROP) at ha_maria.cc:2124
#14 0x003265c8 in drop_open_table (thd=0x79ed8d8, table=0x817d8e8, 

in push:
guilhem@mysql.co...
2009-03-13 15:18:36 
maria_bulk_insert 
sol10
sparc32 sysqa