Bug #90402 innodb async io error handling in io_event
Submitted: 12 Apr 2018 7:39 Modified: 26 Nov 2018 13:43
Reporter: Wei Zhao (OCA) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:mysql-5.7.17 OS:Any
Assigned to: CPU Architecture:Any
Tags: Contribution

[12 Apr 2018 7:39] Wei Zhao
Description:

I have an mysql-5.7 db instance which periodically crashes at below call
stack 1(at the bottom of this page) and reports this error message:

[ERROR] [FATAL] InnoDB: Native Linux AIO interface. io_submit() call failed when resubmitting a partial I/O request on the file ***.

When I use debug version mysqld, it crashes at below call stack 2 periodically.
Note that in call stack 2, the slot->n_bytes is -5. And
after reading the source code of innodb's os0file.cc,
I found that the slot->n_bytes is only possibly set by this assignment

"slot->n_bytes = events[i].res;" in os0file.c:2562 in
function void LinuxAIOHandler::collect().

However, io_event::res is defined as
'unsigned long', it's weird to store a negative value but not define it as
'long'. I didn't find documentation about io_event::res from the doc of
libaio, so I found the source code of aio module in linux kernel here 
https://github.com/torvalds/linux/blob/master/fs/aio.c
and in this file, the code of aio_ret() and aio_complete() functions suggests
that the io_event::res is really used like this: it should have been defined
as type 'ssize_t', and when io_event::res is positive or 0, it means the same
as the value of 'read'/'write' system call, i.e. the number of bytes
read/written; when it's negative, it's the -errno of the async io operation
that this io_event object belongs to. 

Consequently, in innodb we should handle
the error number case, hence my patch. Without this patch in case of EIO (5) error of submitted aio operation, the next resubmit will start reading at a wrong offset and length, causing the error and abortion of call stack 1.

However in case of real storage media corruption, innodb has to somehow stop useless repetitive aio operation, and I'll leave that to you.

==================================================================
1. crash stack of release version

Using host libthread_db library "/lib64/libthread_db.so.1".
Core was generated by `./bin/mysqld --defaults-file=/data/tdsql_run/4158/percona-5.7.17/etc/my_4158.cn'.
Program terminated with signal 6, Aborted.
#0  0x00007fb87461b741 in pthread_kill () from /lib64/libpthread.so.0
Missing separate debuginfos, use: debuginfo-install glibc-2.17-157.tl2.2.x86_64 libaio-0.3.109-13.el7.x86_64 libgcc-4.8.5-4.el7.x86_64 libstdc++-4.8.5-4.el7.x86_64 nss-softokn-freebl-3.16.2.3-13.el7_1.x86_64 zlib-1.2.7-15.el7.x86_64
(gdb) bt
#0  0x00007fb87461b741 in pthread_kill () from /lib64/libpthread.so.0
#1  0x000000000079442c in handle_fatal_signal ()
#2  <signal handler called>
#3  0x00007fb8730071d7 in raise () from /lib64/libc.so.6
#4  0x00007fb8730088c8 in abort () from /lib64/libc.so.6
#5  0x0000000000782655 in ut_dbg_assertion_failed(char const*, char const*, unsigned long) ()
#6  0x00000000011041ab in ib::fatal::~fatal() ()
#7  0x000000000100eb28 in LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) ()
#8  0x000000000100fadd in os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) ()
#9  0x00000000011a98f8 in fil_aio_wait(unsigned long) ()
#10 0x00000000010b2f10 in io_handler_thread ()
#11 0x00007fb874616dc5 in start_thread () from /lib64/libpthread.so.0
#12 0x00007fb8730c974d in clone () from /lib64/libc.so.6

==================================================================
2. crash stack of debug version

[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
Core was generated by `./bin/mysqld --defaults-file=/data/tdsql_run/4158/percona-5.7.17/etc/my_4158.cn'.
Program terminated with signal 6, Aborted.
#0  0x00007f96c8b1f741 in pthread_kill () from /lib64/libpthread.so.0
Missing separate debuginfos, use: debuginfo-install glibc-2.17-157.tl2.2.x86_64 libaio-0.3.109-13.el7.x86_64 libgcc-4.8.5-4.el7.x86_64 libstdc++-4.8.5-4.el7.x86_64 nss-softokn-freebl-3.16.2.3-13.el7_1.x86_64 zlib-1.2.7-15.el7.x86_64
(gdb) bt
#0  0x00007f96c8b1f741 in pthread_kill () from /lib64/libpthread.so.0
#1  0x00000000018d74d8 in my_write_core (sig=6) at /data/home/tdengine/davie/latest/percona-server-5.7.17-11/mysys/stacktrace.c:249
#2  0x0000000000ec4926 in handle_fatal_signal (sig=6) at /data/home/tdengine/davie/latest/percona-server-5.7.17-11/sql/signal_handler.cc:223
#3  <signal handler called>
#4  0x00007f96c750b1d7 in raise () from /lib64/libc.so.6
#5  0x00007f96c750c8c8 in abort () from /lib64/libc.so.6
#6  0x0000000001be26f7 in ut_dbg_assertion_failed (expr=0x22f1958 "static_cast<ulint>(slot->n_bytes) < slot->original_len - n_bytes", 
    file=0x22f11c8 "/data/home/tdengine/davie/latest/percona-server-5.7.17-11/storage/innobase/os/os0file.cc", line=2331) at /data/home/tdengine/davie/latest/percona-server-5.7.17-11/storage/innobase/ut/ut0dbg.cc:67
#7  0x0000000001a68741 in LinuxAIOHandler::resubmit (this=0x7f96033f1d70, slot=0x7f96b9b98700) at /data/home/tdengine/davie/latest/percona-server-5.7.17-11/storage/innobase/os/os0file.cc:2331
#8  0x0000000001a6908f in LinuxAIOHandler::poll (this=0x7f96033f1d70, m1=0x7f96033f1e50, m2=0x7f96033f1e48, request=0x7f96033f1e10) at /data/home/tdengine/davie/latest/percona-server-5.7.17-11/storage/innobase/os/os0file.cc:2617
#9  0x0000000001a69325 in os_aio_linux_handler (global_segment=13, m1=0x7f96033f1e50, m2=0x7f96033f1e48, request=0x7f96033f1e10) at /data/home/tdengine/davie/latest/percona-server-5.7.17-11/storage/innobase/os/os0file.cc:2703
#10 0x0000000001a6e1b7 in os_aio_handler (segment=13, m1=0x7f96033f1e50, m2=0x7f96033f1e48, request=0x7f96033f1e10) at /data/home/tdengine/davie/latest/percona-server-5.7.17-11/storage/innobase/os/os0file.cc:6373
#11 0x0000000001cd85e3 in fil_aio_wait (segment=13) at /data/home/tdengine/davie/latest/percona-server-5.7.17-11/storage/innobase/fil/fil0fil.cc:5930
#12 0x0000000001b7b5a7 in io_handler_thread (arg=0x2ebb468 <n+104>) at /data/home/tdengine/davie/latest/percona-server-5.7.17-11/storage/innobase/srv/srv0start.cc:330
#13 0x00007f96c8b1adc5 in start_thread () from /lib64/libpthread.so.0
#14 0x00007f96c75cd74d in clone () from /lib64/libc.so.6
(gdb) f 7
#7  0x0000000001a68741 in LinuxAIOHandler::resubmit (this=0x7f96033f1d70, slot=0x7f96b9b98700) at /data/home/tdengine/davie/latest/percona-server-5.7.17-11/storage/innobase/os/os0file.cc:2331
2331    /data/home/tdengine/davie/latest/percona-server-5.7.17-11/storage/innobase/os/os0file.cc: No such file or directory.
(gdb) p slot->n_bytes
$1 = -5
(gdb) p *slot
$3 = {pos = 2823, is_reserved = true, reservation_time = 1523425845, buf = 0x7f96a2710000 "", ptr = 0x7f96a2710000 "", type = {m_block_size = 4096, m_type = 65, m_compression = {m_type = Compression::NONE}, m_encryption = {
      m_type = Encryption::NONE, m_key = 0x0, m_klen = 0, m_iv = 0x0, static master_key_id = 0, static uuid = '\000' <repeats 36 times>}}, offset = 5095489536, file = 265, name = 0x7f95b2bfa5d8 "./paysettle/t_sina_middle_detail.ibd", 
  io_already_done = true, space_id = 2831, m1 = 0x7f95b0ff2fd8, m2 = 0x7f96a1b92120, err = DB_SUCCESS, control = {data = 0x7f96b9b98700, key = 0, __pad2 = 0, aio_lio_opcode = 0, aio_reqprio = 0, aio_fildes = 265, u = {c = {
        buf = 0x7f96a2710000, nbytes = 16384, offset = 5095489536, __pad3 = 0, flags = 0, resfd = 0}, v = {vec = 0x7f96a2710000, nr = 16384, offset = 5095489536}, poll = {events = -1569652736, __pad1 = 32662}, saddr = {
        addr = 0x7f96a2710000, len = 16384}}}, ret = 0, n_bytes = -5, len = 16384, original_len = 16384, buf_block = 0x0, skip_punch_hole = false}
(gdb) p n_bytes
$4 = 0
(gdb) 

==================================================================

How to repeat:
it doesn't seem to relate to specific data or query, it happens in case of storage media block corruption.
[12 Apr 2018 7:41] Wei Zhao
this patch handles the error case of a submitted aio operation

(*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Contribution: idb_aio_error_check.diff (application/octet-stream, text), 937 bytes.

[12 Apr 2018 7:51] MySQL Verification Team
Hello Wei Zhao,

Thank you for the bug report and contribution.

Thanks,
Umesh
[14 Nov 2018 8:28] Daniƫl van Eeden
On MySQL 8.0.13:

2018-11-14T02:05:20.170317Z 86292 [ERROR] [MY-000035] [Server] Disk is full writing '../log/relaylog.007577' (OS errno 28 - No space left on device). Waiting for someone to free space... Retry in 60 secs. Message reprinted in 600 secs.
2018-11-14T02:05:44.997259Z 0 [ERROR] [MY-011825] [InnoDB] [FATAL] Native Linux AIO interface. io_submit() call failed when resubmitting a partial I/O request on the file ./app/flat_cdf_new.ibd.
2018-11-14T02:05:44.997308Z 0 [ERROR] [MY-013183] [InnoDB] Assertion failure: ut0ut.cc:620 thread 140434978346752
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/8.0/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
02:05:44 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

key_buffer_size=268435456
read_buffer_size=131072
max_used_connections=10027
max_threads=10000
thread_count=11
connection_count=10
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 11892769 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0 thread_stack 0x46000
/usr/sbin/mysqld(my_print_stacktrace(unsigned char*, unsigned long)+0x3d) [0x1c1f2cd]
/usr/sbin/mysqld(handle_fatal_signal+0x423) [0xdafab3]
/lib64/libpthread.so.0(+0xf6d0) [0x7fbed446b6d0]
/lib64/libc.so.6(gsignal+0x37) [0x7fbed2782277]
/lib64/libc.so.6(abort+0x148) [0x7fbed2783968]
/usr/sbin/mysqld(ut_dbg_assertion_failed(char const*, char const*, unsigned long)+0x2c2) [0x1ec1fb2]
/usr/sbin/mysqld(ib::fatal::~fatal()+0x129) [0x1ec3c49]
/usr/sbin/mysqld(LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*)+0x3d8) [0x1db1718]
/usr/sbin/mysqld(os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*)+0x58b) [0x1db3a6b]
/usr/sbin/mysqld(fil_aio_wait(unsigned long)+0x51) [0x1fcdc01]
/usr/sbin/mysqld() [0x1e607e8]
/usr/sbin/mysqld(std::thread::_State_impl<std::thread::_Invoker<std::tuple<Runnable, void (*)(unsigned long), unsigned long> > >::_M_run()+0x68) [0x1e60878]
/usr/sbin/mysqld() [0x229f5af]
/lib64/libpthread.so.0(+0x7e25) [0x7fbed4463e25]
/lib64/libc.so.6(clone+0x6d) [0x7fbed284abad]
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.
[26 Nov 2018 13:43] Daniel Price
Posted by developer:
 
Fixed as of the upcoming 5.7.26, 8.0.15 release, and here's the changelog entry:

A Linux AIO handler function failed to check if completed I/O events
succeeded.