MySQL Bugs: #68895: Various assertions and crashes when running out of space

Bug #68895	Various assertions and crashes when running out of space
Submitted:	9 Apr 2013 7:35	Modified:	10 Apr 2013 15:36
Reporter:	Roel Van de Paar	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S1 (Critical)
Version:	5.6	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
2013-04-08 19:59:38 7f6b9fda4700 InnoDB: Error: Write to file ./query19542/#sql-ib10080.ibd failed at offset 1048576.
InnoDB: 1048576 bytes should have been written, only 73728 were written.
InnoDB: Operati2013-04-08 19:59:38 7f6b9fda4700 InnoDB: Error: Write to file ./query19542/#sql-ib10080.ibd failed at offset 753664.
InnoDB: 16384 bytes should have been written, only -1 were written.
InnoDB: Operating system error number 28.
InnoDB: Check that your OS and file system support files of this size.
InnoDB: Check also that the disk is not full or a disk quota exceeded.
InnoDB: Error number 28 means 'No space left on device'.
InnoDB: Some operating system error numbers are described at
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html
2013-04-08 19:59:38 7f6b9fda4700  InnoDB: Assertion failure in thread 140100220110592 in file btr0btr.cc line 693
InnoDB: Failing assertion: mach_read_from_4(seg_header + FSEG_HDR_SPACE) == space

How to repeat:
ENOSPC + right conditions

Suggested fix:
Fix Assert

Query (7f6b3c03fa00): ALTER TABLE query19542 . `t1` DROP COLUMN `c72`

core file corrupt/no info.

Full error log

Attachment: master_558_090413-0037.err (application/octet-stream, text), 20.59 KiB.

These sort of bugs can be verified on single occurrence only; developer may be able to work our relatively easy where the issue is (and can still set the bug back to need info if the issue is not clear from code review).

I can verify hitting this assertion, and other crashes when datadir is full and random DDL is happening (and failing).

5.6.12:
InnoDB: Assertion failure in thread 9312 in file btr0btr.cc line 693
InnoDB: Failing assertion: mach_read_from_4(seg_header + FSEG_HDR_SPACE) == space
InnoDB: We intentionally generate a memory trap.
mysqld.exe!my_sigabrt_handler()[my_thr_init.c:499]
mysqld.exe!raise()[winsig.c:593]
mysqld.exe!abort()[abort.c:81]
mysqld.exe!btr_root_fseg_validate()[btr0btr.cc:693]
mysqld.exe!btr_free_but_not_root()[btr0btr.cc:1662]
mysqld.exe!dict_drop_index_tree()[dict0crea.cc:772]
mysqld.exe!row_undo_ins_remove_clust_rec()[row0uins.cc:126]
mysqld.exe!row_undo_ins()[row0uins.cc:460]
mysqld.exe!row_undo()[row0undo.cc:305]
mysqld.exe!row_undo_step()[row0undo.cc:350]
mysqld.exe!que_thr_step()[que0que.cc:1103]
mysqld.exe!que_run_threads_low()[que0que.cc:1170]
mysqld.exe!que_run_threads()[que0que.cc:1210]
mysqld.exe!trx_rollback_to_savepoint_low()[trx0roll.cc:113]
mysqld.exe!trx_rollback_to_savepoint()[trx0roll.cc:158]
mysqld.exe!row_create_index_for_mysql()[row0mysql.cc:2458]
mysqld.exe!create_index()[ha_innodb.cc:8778]
mysqld.exe!ha_innobase::create()[ha_innodb.cc:9586]
mysqld.exe!ha_create_table()[handler.cc:4686]
mysqld.exe!mysql_alter_table()[sql_table.cc:8190]
mysqld.exe!Sql_cmd_alter_table::execute()[sql_alter.cc:313]
mysqld.exe!mysql_execute_command()[sql_parse.cc:4880]
mysqld.exe!mysql_parse()[sql_parse.cc:6173]
mysqld.exe!dispatch_command()[sql_parse.cc:1339]
mysqld.exe!do_command()[sql_parse.cc:1044]
mysqld.exe!do_handle_one_connection()[sql_connect.cc:977]
mysqld.exe!handle_one_connection()[sql_connect.cc:895]
mysqld.exe!pfs_spawn_thread()[pfs.cc:1856]
mysqld.exe!pthread_start()[my_winthread.c:63]
mysqld.exe!_callthreadstartex()[threadex.c:314]
mysqld.exe!_threadstartex()[threadex.c:292]

I used a small size ramdisk and random create/alter/drop table statements.

Another one when adding a column to a table in 5.7:

mysqld.exe!btr_page_split_and_insert()[btr0btr.cc:2913]
mysqld.exe!btr_cur_pessimistic_insert()[btr0cur.cc:1624]
mysqld.exe!row_merge_insert_index_tuples()[row0merge.cc:2377]
mysqld.exe!row_merge_build_indexes()[row0merge.cc:3581]
mysqld.exe!ha_innobase::inplace_alter_table()[handler0alter.cc:4144]
mysqld.exe!mysql_inplace_alter_table()[sql_table.cc:6535]
mysqld.exe!mysql_alter_table()[sql_table.cc:8253]
mysqld.exe!Sql_cmd_alter_table::execute()[sql_alter.cc:316]
mysqld.exe!mysql_execute_command()[sql_parse.cc:4634]
mysqld.exe!mysql_parse()[sql_parse.cc:5965]
mysqld.exe!dispatch_command()[sql_parse.cc:1334]
mysqld.exe!do_command()[sql_parse.cc:1034]
mysqld.exe!do_handle_one_connection()[sql_connect.cc:982]
mysqld.exe!handle_one_connection()[sql_connect.cc:900]
mysqld.exe!pfs_spawn_thread()[pfs.cc:1925]
mysqld.exe!pthread_start()[my_winthread.c:63]
mysqld.exe!_callthreadstartex()[threadex.c:314]
mysqld.exe!_threadstartex()[threadex.c:292]

This bug report is probably a good topic for a future worklog.

Another consequence if running out of space, on 5.7.2
InnoDB: Assertion failure in thread 7564 in file row0purge.cc line 512
InnoDB: Failing assertion: success

mysqld.exe!my_sigabrt_handler()[my_thr_init.c:516]
mysqld.exe!raise()[winsig.c:593]
mysqld.exe!abort()[abort.c:81]
mysqld.exe!row_purge_remove_sec_if_poss()[row0purge.cc:513]
mysqld.exe!row_purge_del_mark()[row0purge.cc:542]
mysqld.exe!row_purge_record_func()[row0purge.cc:822]
mysqld.exe!row_purge()[row0purge.cc:881]
mysqld.exe!row_purge_step()[row0purge.cc:960]
mysqld.exe!que_thr_step()[que0que.cc:1097]
mysqld.exe!que_run_threads_low()[que0que.cc:1162]
mysqld.exe!que_run_threads()[que0que.cc:1202]
mysqld.exe!trx_purge()[trx0purge.cc:1247]
mysqld.exe!srv_do_purge()[srv0srv.cc:2536]
mysqld.exe!srv_purge_coordinator_thread()[srv0srv.cc:2713]

Nice work Shane

One more:

2013-04-05 09:44:12 19421 [Note] /data/opt/roel/Percona-Server-5.6.8-alpha60.2-314-debug.Linux.x86_64/bin/mysqld-debug: ready for connections.
Version: '5.6.10-alpha60.2-debug-log'  socket: '/ssd/296158/current1_1/tmp/master.sock'  port: 13000  Percona Server with XtraDB (GPL), Release alpha60.2, Revis
ion 314-debug
2013-04-05 09:44:49 7f6df1fc1700  InnoDB: File name ./ib_log_archive_0000000201363968
2013-04-05 09:44:49 7f6df1fc1700  InnoDB: File operation call: 'Linux aio' returned OS error 0.
2013-04-05 09:44:49 7f6df1fc1700  InnoDB: Cannot continue operation.
2013-04-05 09:44:49 7f6df1fc1700  InnoDB: Assertion failure in thread 140110187992832 in file os0file.cc line 662
InnoDB: Failing assertion: 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.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
06:44:49 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also poss  [log ends abruptly here]

In this case, writing ib_log_archive_x is a feature within Percona Server, but likely the associated assertion/issue etc. is not. I also have the callstack for this issue:

Thread 1 (Thread 0x7f6df1fc1700 (LWP 19424)):
+bt
#0  0x00007f6e0460b69c in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000000673dce in handle_fatal_signal (sig=6) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/sql/signal_handler.cc:249
#2  <signal handler called>
#3  0x00007f6e032ba8a5 in raise () from /lib64/libc.so.6
#4  0x00007f6e032bc085 in abort () from /lib64/libc.so.6
#5  0x0000000000a02d2a in os_file_handle_error_cond_exit (name=0x7f6dc0028018 "./ib_log_archive_0000000201363968", operation=0xdb1bcc "Linux aio", should_exit=<value optimized out>, on_error_silent=<value optimized out>) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/storage/innobase/os/os0file.cc:662
#6  0x0000000000a03150 in os_file_handle_error (global_seg=1, message1=0x7f6df1fc0e58, message2=0x7f6df1fc0e50, type=0x7f6df1fc0e48) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/storage/innobase/os/os0file.cc:681
#7  os_aio_linux_handle (global_seg=1, message1=0x7f6df1fc0e58, message2=0x7f6df1fc0e50, type=0x7f6df1fc0e48) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/storage/innobase/os/os0file.cc:5095
#8  0x0000000000b5c19b in fil_aio_wait (segment=1) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/storage/innobase/fil/fil0fil.cc:5401
#9  0x0000000000a9f0c8 in io_handler_thread (arg=<value optimized out>) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/storage/innobase/srv/srv0start.cc:477
#10 0x00007f6e04606851 in start_thread () from /lib64/libpthread.so.0
#11 0x00007f6e0337011d in clone () from /lib64/libc.so.6

From the developer: this is a fail of async write into archived log, seems like InnoDB doesn't have any suitable handling of failed ones, except retry. However for ENOSPC it just fails.

Stacks for that last issue

Attachment: gdb_535_100413-0811_STD.txt (text/plain), 27.52 KiB.

thread apply all bt FULL on core

Attachment: gdb_535_100413-0811_FULL.txt (text/plain), 86.58 KiB.

2013-04-05 09:44:24 19629 [Note] /data/opt/roel/Percona-Server-5.6.8-alpha60.2-314-debug.Linux.x86_64/bin/mysqld-debug: ready for connections.
Version: '5.6.10-alpha60.2-debug-log' socket: '/ssd/296158/current1_5/tmp/master.sock' port: 13080 Percona Server with XtraDB (GPL), Release alpha60.2, Revision 314-debug
2013-04-05 09:44:49 7fdcd9143700 InnoDB: Error: Write to file /ssd/296158/_epoch/1365144257994225052/ib_log_archive_0000000250165760 failed at offset 0.
InnoDB: 1024 bytes should have been written, only -1 were written.
InnoDB: Operating system error number 28.
InnoDB: Check that your OS and file system support files of this size.
InnoDB: Check also that the disk is not full or a disk quota exceeded.
InnoDB: Error number 28 means 'No space left on device'.
InnoDB: Some operating system error numbers are described at
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html
2013-04-05 09:44:49 7fdcd9143700 InnoDB: Assertion failure in thread 140586511513344 in file fil0fil.cc line 5356
InnoDB: Failing assertion: ret
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeate/data/opt/roel/Percona-Server-5.6.8-alpha60.2-314-debug.Linux.x86_64/bin/mysqld-debug[0xa9f0c8]
/lib64/libpthread.so.0(+0x7851)[0x7fdceb9f8851]
/lib64/libc.so.6(clone+0x6d)[0x7fdcea76211d]
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
Writing a core file

For that last one;

#4  0x00007fdcea6ae085 in abort () from /lib64/libc.so.6
#5  0x0000000000b6071f in fil_io (type=<value optimized out>, sync=<value optimized out>, space_id=61, zip_size=1, block_offset=<value optimized out>, byte_offset=<value optimized out>, len=1024, buf=0x25bce00, message=0x14f3960) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/storage/innobase/fil/fil0fil.cc:5356

Stacks for that last issue

Attachment: gdb_413_100413-0827_STD.txt (text/plain), 28.06 KiB.

thread apply all bt FULL on core

Attachment: gdb_413_100413-0827_FULL.txt (text/plain), 91.44 KiB.

And one more

2013-04-05 10:43:47 24982 [Note] /data/opt/roel/Percona-Server-5.6.8-alpha60.2-314-debug.Linux.x86_64/bin/mysqld-debug: ready for connections.
Version: '5.6.10-alpha60.2-debug-log'  socket: '/ssd/296158/current1_2/tmp/master.sock'  port: 13020  Percona Server with XtraDB (GPL), Release alpha60.2, Revision 314-debug
2013-04-05 10:44:26 7fbd706a7700  InnoDB: File name ./ib_log_archive_0000000251693568
2013-04-05 10:44:26 7fbd706a7700  InnoDB: File operation call: 'Linux aio' returned OS error 0.
2013-04-05 10:44:26 7fbd706a7700  InnoDB: Cannot continue operation.
2013-04-05 10:44:26 7fbd706a7700  InnoDB: Assertion failure in thread 140451611571968 in file os0file.cc line 662
InnoDB: Failing assertion: 0
InnoDB: We intentionally generate a memory trap.

No core/traces available for just that last one.

Agree with Shane on worklog idea.

Maybe some sort of buffer (on disk) could be per-allocated on mysqld startup. Then, when OS reports ENOSPC this buffer could be used to at least cleanly bring mysqld down (fast shutdown). Need to figure out proper buffer sizing.

To reproduce, run this a near full disk : 800M free :

drop database test_case2;
create database test_case2;
use test_case2;
set global query_cache_size = 0;
set global innodb_flush_log_at_trx_commit = 2;
drop table if exists t1;
create table t1(
id int primary key auto_increment,
k  varchar(50),
value varchar(1000), unique key(k)) engine=InnoDB;
set @t1 =(select now());
set @i := 1;
insert into t1(k,value) values(@i:=@i+1,repeat('a',rand()*1000)); 
insert into t1(k,value) values(@i:=@i+1,repeat('a',rand()*1000)); 
replace into t1(k,value) select @i:=@i+1,repeat('a',rand()*1000) from t1 t1, t1 t2, t1 t3, t1 t4, t1 t5, t1 t6, t1 t7, t1 t8, t1 t9, t1 t10, t1 t11, t1 t12, t1 t13, t1 t14, t1 t15, t1 t16, t1 t17,
t1 t18, t1 t19, t1 t20;
set @t2 =(select now());
select @@version,timediff(@t2,@t1) duration;

analyze table t1\G
show table status like 't1'\G
delete from t1 where mod(id,2) = 0; 
show table status like 't1'\G
drop table if exists t1_defrag;
create table t1_defrag like t1; 
insert into t1_defrag select * from t1 limit 20000;
analyze table t1\G
analyze table t1_defrag\G
show table status like 't1'\G
show table status like 't1_defrag'\G
alter table t1 row_format=dynamic;

(gdb) where
#0  0x0000003541c0c63c in pthread_kill () from /lib64/libpthread.so.0
#1  0x000000000069d75a in handle_fatal_signal (sig=11) at /export/home/pb2/build/sb_0-10116985-1377876331.31/mysqlcom-pro-5.6.14/sql/signal_handler.cc:248
#2  <signal handler called>
#3  btr_page_split_and_insert (flags=23, cursor=0x7ff6b2429a00, offsets=0x7ff6b2429a88, heap=0x7ff6b2429ab8, tuple=0x7ff64c024a48, n_ext=0, mtr=0x7ff6b2429560)
    at /export/home/pb2/build/sb_0-10116985-1377876331.31/mysqlcom-pro-5.6.14/storage/innobase/btr/btr0btr.cc:2918
#4  0x0000000000aacfc0 in btr_cur_pessimistic_insert (flags=23, cursor=0x7ff6b2429a00, offsets=0x7ff6b2429a88, heap=0x7ff6b2429ab8, entry=0x7ff64c024a48,
    rec=<value optimized out>, big_rec=0x7ff6b2429a98, n_ext=0, thr=0x0, mtr=0x7ff6b2429560)
    at /export/home/pb2/build/sb_0-10116985-1377876331.31/mysqlcom-pro-5.6.14/storage/innobase/btr/btr0cur.cc:1613
#5  0x0000000000a3e14d in row_merge_insert_index_tuples (trx_id=9720113, index=0x7ff64c025808, old_table=0x7ff64c0148a8, fd=88, block=<value optimized out>)
    at /export/home/pb2/build/sb_0-10116985-1377876331.31/mysqlcom-pro-5.6.14/storage/innobase/row/row0merge.cc:2362
#6  0x0000000000a41d0e in row_merge_build_indexes (trx=0x7ff64c00afc8, old_table=0x7ff64c0148a8, new_table=0x7ff64c009a28, online=true, indexes=0x7ff64c013088,
    key_numbers=0x7ff64c013098, n_indexes=2, table=0x7ff64c01b120, add_cols=0x0, col_map=0x7ff64c0130f0, add_autoinc=18446744073709551615, sequence=...)
    at /export/home/pb2/build/sb_0-10116985-1377876331.31/mysqlcom-pro-5.6.14/storage/innobase/row/row0merge.cc:3561
#7  0x00000000009c94d5 in ha_innobase::inplace_alter_table (this=0x7ff64c00ddd0, altered_table=0x7ff64c01b120, ha_alter_info=0x7ff6b242af30)
    at /export/home/pb2/build/sb_0-10116985-1377876331.31/mysqlcom-pro-5.6.14/storage/innobase/handler/handler0alter.cc:3885
#8  0x000000000076b2e5 in ha_inplace_alter_table (thd=0x1a30e00, table_list=0x7ff64c004ca0, table=0x7ff64c016e60, altered_table=0x7ff64c01b120, ha_alter_info=0x7ff6b242af30,
    inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7ff6b242bc50, alter_ctx=0x7ff6b2429f20)
    at /export/home/pb2/build/sb_0-10116985-1377876331.31/mysqlcom-pro-5.6.14/sql/handler.h:2856
#9  mysql_inplace_alter_table (thd=0x1a30e00, table_list=0x7ff64c004ca0, table=0x7ff64c016e60, altered_table=0x7ff64c01b120, ha_alter_info=0x7ff6b242af30,
    inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7ff6b242bc50, alter_ctx=0x7ff6b2429f20)
    at /export/home/pb2/build/sb_0-10116985-1377876331.31/mysqlcom-pro-5.6.14/sql/sql_table.cc:6500
#10 0x000000000076e5b6 in mysql_alter_table (thd=0x1a30e00, new_db=<value optimized out>, new_name=<value optimized out>, create_info=0x7ff6b242c460,
    table_list=0x7ff64c004ca0, alter_info=0x7ff6b242c540, order_num=0, order=0x0, ignore=false)
    at /export/home/pb2/build/sb_0-10116985-1377876331.31/mysqlcom-pro-5.6.14/sql/sql_table.cc:8192
#11 0x000000000086dbf9 in Sql_cmd_alter_table::execute (this=<value optimized out>, thd=0x1a30e00)
    at /export/home/pb2/build/sb_0-10116985-1377876331.31/mysqlcom-pro-5.6.14/sql/sql_alter.cc:313
#12 0x000000000071f015 in mysql_execute_command (thd=0x1a30e00) at /export/home/pb2/build/sb_0-10116985-1377876331.31/mysqlcom-pro-5.6.14/sql/sql_parse.cc:4936
#13 0x00000000007229a8 in mysql_parse (thd=0x1a30e00, rawbuf=0x7ff64c004ba0 "alter table t1 row_format=dynamic", length=<value optimized out>,
    parser_state=<value optimized out>) at /export/home/pb2/build/sb_0-10116985-1377876331.31/mysqlcom-pro-5.6.14/sql/sql_parse.cc:6235
#14 0x0000000000723d7b in dispatch_command (command=COM_QUERY, thd=0x1a30e00, packet=<value optimized out>, packet_length=33)
    at /export/home/pb2/build/sb_0-10116985-1377876331.31/mysqlcom-pro-5.6.14/sql/sql_parse.cc:1334
#15 0x0000000000725b77 in do_command (thd=0x1a30e00) at /export/home/pb2/build/sb_0-10116985-1377876331.31/mysqlcom-pro-5.6.14/sql/sql_parse.cc:1036
#16 0x00000000006edcf6 in do_handle_one_connection (thd_arg=0x1a30e00) at /export/home/pb2/build/sb_0-10116985-1377876331.31/mysqlcom-pro-5.6.14/sql/sql_connect.cc:982
#17 0x00000000006eddd5 in handle_one_connection (arg=0x1fe0b60) at /export/home/pb2/build/sb_0-10116985-1377876331.31/mysqlcom-pro-5.6.14/sql/sql_connect.cc:898
#18 0x00000000009a7db6 in pfs_spawn_thread (arg=<value optimized out>) at /export/home/pb2/build/sb_0-10116985-1377876331.31/mysqlcom-pro-5.6.14/storage/perfschema/pfs.cc:1858
#19 0x0000003541c077f1 in start_thread () from /lib64/libpthread.so.0
#20 0x00000033230e5ccd in clone () from /lib64/libc.so.6

See also bug #70938