Crash with innodb_lazy_drop_table=ON

[Vadim Tkachenko]

With innodb_lazy_drop_table I've got crash

110419 9:20:46 InnoDB: Assertion failure in thread 1342912832 in file fil/fil0fil.c line 834
InnoDB: Failing assertion: UT_LIST_GET_LEN(system->LRU) > 0
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.

It is not easy repeatable, I have that innodb_buffer_pool_size=200G

[Vadim Tkachenko (vadim-tk)]

I was able to repeat crash second time.
bt is
0x0000003c60030265 in raise () from /lib64/libc.so.6
(gdb) bt
#0 0x0000003c60030265 in raise () from /lib64/libc.so.6
#1 0x0000003c60031d10 in abort () from /lib64/libc.so.6
#2 0x00000000007b6c49 in fil_node_close_file (node=0x2ae00773d298, system=0xe5e1998) at fil/fil0fil.c:834
#3 0x00000000007b7d80 in fil_node_free (id=<value optimized out>, x_latched=1) at fil/fil0fil.c:1050
#4 fil_space_free (id=<value optimized out>, x_latched=1) at fil/fil0fil.c:1376
#5 0x00000000007bd4d2 in fil_delete_tablespace (id=13045) at fil/fil0fil.c:2310
#6 0x0000000000738495 in row_drop_table_for_mysql (name=<value optimized out>, trx=0x2ae00d1e2098,
    drop_db=<value optimized out>) at row/row0mysql.c:3415
#7 0x00000000006e6fbd in ha_innobase::delete_table (this=<value optimized out>,
    name=0x50a3fdc0 "./test1/ts_1000") at handler/ha_innodb.cc:7442
#8 0x000000000065ea56 in ha_delete_table (thd=0x2ae10813f900, table_type=0xd353220,
    path=<value optimized out>, db=0x2ae00cc67830 "test1", alias=0x2ae00cc674c8 "ts_1000",
    generate_warning=true) at handler.cc:2005
#9 0x00000000006658ed in mysql_rm_table_part2 (thd=0x2ae10813f900, tables=0x2ae00cc67500, if_exists=false,
    drop_temporary=false, drop_view=false, dont_log_query=false) at sql_table.cc:2071
#10 0x0000000000665e67 in mysql_rm_table (thd=0x2ae10813f900, tables=0x2ae00cc67500, if_exists=0 '\000',
    drop_temporary=<value optimized out>) at sql_table.cc:1850
#11 0x000000000058ddcc in mysql_execute_command (thd=0x2ae10813f900) at sql_parse.cc:3549
#12 0x0000000000590f09 in mysql_parse (thd=0x2ae10813f900, rawbuf=0x2ae00cc67430 "DROP TABLE ts_1000",
    length=18, found_semicolon=0x50a41e28) at sql_parse.cc:6219
#13 0x0000000000591939 in dispatch_command (command=COM_QUERY, thd=0x2ae10813f900,
    packet=<value optimized out>, packet_length=<value optimized out>) at sql_parse.cc:1278
#14 0x00000000005925d0 in do_command (thd=0x2ae10813f900) at sql_parse.cc:903
#15 0x00000000005843b1 in handle_one_connection (arg=0x2ae10813f900) at sql_connect.cc:1751
#16 0x0000003c6080673d in start_thread () from /lib64/libpthread.so.0
#17 0x0000003c600d3d1d in clone () from /lib64/libc.so.6

[Vadim Tkachenko (vadim-tk)]

scripts to repeat.
1. create tables
for i in `seq 1 1000`
do
mysql -Bse "CREATE TABLE ts_$i ( begin_time int(11) NOT NULL, end_time int(11) NOT NULL, PRIMARY KEY (begin_time)) ENGINE=InnoDB" test1
done

2. drop tables
for i in `seq 1 1000`
do
mysql -Bse "DROP TABLE ts_$i" test1
done

[Yasufumi Kinoshita (yasufumi-kinoshita)]

fixed directly
5.1.56 rev.225
5.5.11 rev.107

I confirmed all possible paths and the tiny fix is enough.

fil_node_prepare_for_io() or fil_node_complete_io() are never called after fil_space_free() from fil_delete_tablespace(), even if innodb_lazy_drop_table is enabled.
(protected by buf_page_struct::space_was_being_deleted flag enough already)

[Vadim Tkachenko (vadim-tk)]

Yasufumi,

I do not see 5.1.56 rev.225 in
https://code.launchpad.net/~percona-dev/percona-server/5.1.56

[Alexey Kopytov (akopytov)]

Vadim,

That's because I had to merge from trunk before pushing my revision. Which resulted in multiple revisions, including the fix for this bug, being wrapped into a single merge revision. So the new number for this revision is 222.1.3 which is wrapped into rev. 224.

[Stewart Smith (stewart)]

seems to have been fixed in old 5.1

[Hui Liu (hickey)]

Any updates for this issue in 5.5? A long long time since it's filed.

[Laurynas Biveinis (laurynas-biveinis)]

It looks like it was fixed long long time ago too - in 5.1.56 and 5.5.11. Do you still experience this crash with a recent version?

[Hui Liu (hickey)]

Not hit in 5.5.18, neither other issues, at least until now.

[guyue.zql (guyue-zql)]

yes , our server hit it again today , the error descrption: version 5518

 109 130712 13:32:56 InnoDB: Error: Write to file ./mms/t_pdtcatagory.ibd failed at offset 0 32768.
 110 InnoDB: 65536 bytes should have been written, only 0 were written.
 111 InnoDB: Operating system error number 9.
 112 InnoDB: Check that your OS and file system support files of this size.
 113 InnoDB: Check also that the disk is not full or a disk quota exceeded.
 114 InnoDB: Error number 9 means 'Bad file descriptor'.
 115 InnoDB: Some operating system error numbers are described at
 116 InnoDB: http://dev.mysql.com/doc/refman/5.5/en/operating-system-error-codes.html
 117 130712 13:32:56 InnoDB: Assertion failure in thread 47904180700928 in file os0file.c line 5020
 118 InnoDB: Failing assertion: ret
 119 InnoDB: We intentionally generate a memory trap.
 120 InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
 121 InnoDB: If you get repeated assertion failures or crashes, even
 122 InnoDB: immediately after the mysqld startup, there may be
 123 InnoDB: corruption in the InnoDB tablespace. Please refer to
 124 InnoDB: http://dev.mysql.com/doc/refman/5.5/en/forcing-innodb-recovery.html
 125 InnoDB: about forcing recovery.
 126 130712 13:32:56 - mysqld got signal 6 ;

 109 130712 13:32:56 InnoDB: Error: Write to file ./mms/t_pdtcatagory.ibd failed at offset 0 32768.
 110 InnoDB: 65536 bytes should have been written, only 0 were written.
 111 InnoDB: Operating system error number 9.
 112 InnoDB: Check that your OS and file system support files of this size.
 113 InnoDB: Check also that the disk is not full or a disk quota exceeded.
 114 InnoDB: Error number 9 means 'Bad file descriptor'.
 115 InnoDB: Some operating system error numbers are described at
 116 InnoDB: http://dev.mysql.com/doc/refman/5.5/en/operating-system-error-codes.html
 117 130712 13:32:56 InnoDB: Assertion failure in thread 47904180700928 in file os0file.c line 5020
 118 InnoDB: Failing assertion: ret

[Laurynas Biveinis (laurynas-biveinis)]

Please file a new bug re. OS error 9. Thanks!

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-473