MySQL在删除表时I/O错误原因分析
问题现象最近使用sysbench测试MySQL，由于测试时间较长，写了一个脚本按prepare->run->cleanup的顺序在后台跑着。跑完后察看日志发现一个问题，MySQL服务的错误日志中出现多条类似以下信息的报错： InnoDB: Trying to do I/O to a tablespace which does not exist. I/O type: read, page: , I/O length: 16384 bytes。看起来是I/O出现了错误，但MySQL进程并未崩溃，sysbench客户端也没有报错。发现问题过程根据报错的时间记录以及脚本输出的各个阶段的时间点对比，确定了当时脚本正在执行的命令为：sysbench --tables=100 --table-size=4000000 --threads=50 --mysql-db=sbtest --time=300 oltp_delete cleanup
重新手动执行一遍这个用例，却没有再出现同样的情况。但是用脚本执行却依然能够发现这个错误信息。初步怀疑是run和cleanup之间不能间隔太久才会触发这个问题。由于执行一遍100G数据量的时间较长，重现代价较大，先尝试缩减用例数据量。将—table-size=4000000修改为2000000，此时执行脚本，又不会触发这个问题了，最后将—table-size=3000000可以稳定触发又能减少部分重现时间。为了确认是否间隔太长会导致不能复现，修改脚本在run和cleanup两个阶段之间sleep 10秒，果然不会触发这个错误信息。修改为sleep 5秒则还能触发，不过报错条数已有所减少。问题调查察看对应版本mysql5.7.22的代码，发现这个报错只有一个位置：fil0fil.cc文件的第5578行fil_io()函数内。
直接使用gdb调试，在这个位置加上断点，并执行可复现的脚本，得到以下堆栈：(gdb) bt#0fil_io (type=..., sync=sync@entry=false, page_id=..., page_size=..., byte_offset=byte_offset@entry=0, len=16384, buf=0x7f9ead544000, message=message@entry=0x7f9ea8ce9c78) at mysql-5.7.22/storage/innobase/fil/fil0fil.cc:5580#10x00000000010f99fa in buf_read_page_low (err=0x7f9ddaffc72c, sync=<optimized out>, type=0, mode=<optimized out>, page_id=..., page_size=..., unzip=true) at mysql-5.7.22/storage/innobase/buf/buf0rea.cc:195#20x00000000010fc5fa in buf_read_ibuf_merge_pages (sync=sync@entry=false, space_ids=space_ids@entry=0x7f9ddaffc7e0, page_nos=page_nos@entry=0x7f9ddaffc7a0, n_stored=2) at mysql-5.7.22/storage/innobase/buf/buf0rea.cc:834#30x0000000000f3a86c in ibuf_merge_pages (n_pages=n_pages@entry=0x7f9ddaffce30, sync=sync@entry=false) at mysql-5.7.22/storage/innobase/ibuf/ibuf0ibuf.cc:2552#40x0000000000f3a94a in ibuf_merge (sync=false, sync=false, n_pages=0x7f9ddaffce30) at mysql-5.7.22/storage/innobase/ibuf/ibuf0ibuf.cc:2656#5ibuf_merge_in_background (full=full@entry=false) at mysql-5.7.22/storage/innobase/ibuf/ibuf0ibuf.cc:2721#60x000000000102bcf4 in srv_master_do_active_tasks () at mysql-5.7.22/storage/innobase/srv/srv0srv.cc:2132#7srv_master_thread (arg=<optimized out>) at mysql-5.7.22/storage/innobase/srv/srv0srv.cc:2383#80x00007fa003eeddc5 in start_thread () from /lib64/libpthread.so.0#90x00007fa002aab74d in clone () from /lib64/libc.so.6
很明显这是后台线程在做insert buffer merge操作。此时发现space->stop_new_ops为true，也就是要处理的页面所属的space正在被删除。为什么会去操作正在被删除的space呢？这需要调查下insert buffer功能、insert buffer merge的流程以及删除表的流程。insert buffer背景知识insert buffer是一种特殊的数据结构（B+ tree），当辅助索引页面不在缓冲池中时，它会将更改缓存起来，稍后在页面被其他读取操作加载到缓冲池中时合并。MySQL最初引进这个功能的时候只能缓存insert操作，所以叫做insert buffer，现在这些操作可以是 INSERT, UPDATE, or DELETE(DML)，所以改叫做change buffer了（本文依然以insert buffer描述），但源码中依然以ibuf作为标识。这个功能把若干对同一页面的更新缓存起来，合并为一次性更新操作，减少了IO，并转化随机IO为顺序IO,这样可以避免随机IO带来性能损耗，提高数据库的写性能。相关insert buffer merge逻辑当buffer page读入buffer pool时，就会进行insert buffer merge。主要有几个场景会出现merge过程：
[*]当页面被读入缓冲池时，读取完成后先进行ibuf的merge，然后页面才可用；
[*]merge操作作为后台任务执行。 innodb_io_capacity参数可设置InnoDB后台任务每次merge过程的页面数上限；
[*]在崩溃恢复期间，当索引页被读入缓冲池时，将执行对应页的insert buffer merge；
[*]insert buffer具有持久性，系统崩溃不会导致它失效。重启后，insert buffer merge操作将恢复正常；
[*]服务器关闭时可使用—innodb-fast-shutdown = 0强制进行ibuf的完全合并。
我们这次的问题很明显属于第二种情况。innodb主线程(svr_master_thread）会每隔一秒主动进行一次insert buffer的merge操作。先判断过去1s之内服务器是否发生过活动（插入元组到页面、undo表上的行操作等），如果发生过，则merge的最大页面数为innodb_io_capacity设定的5%。如果没有则merge的最大页面数为innodb_io_capacity设定的值。innodb主线程(svr_master_thread）merge的主流程如下：
[*]主线程从ibuf树的叶子节点读取页号和space号，并记录到一个二元数组中（未加锁）；
[*]主线程对二元组中space进行检测是否在表空间缓存中，如不在，说明已经被删除了，删除对应ibuf的记录；
[*]主线程判断是否对一个正在删除的space进行异步读取操作，如果是，报错，并删除对应ibuf的记录，转到过程2继续下一个数组元素的判断；
[*]如果一切判断正常，主线程发出async io请求，async读取需要被merge的索引页面；
[*]I/O handler 线程，在接受到完成的async I/O之后，进行merge操作；
[*]进行merge的时候调用fil_space_acquire对space->n_pending_ops进行自增。避免删除操作并发；
[*]执行完毕后调用fil_space_release对space->n_pending_ops进行自减。
相关删除表的逻辑
[*]对fil_system->mutex加锁，设置sp->stop_new_ops = true，标记space正在删除，不允许对它进行新操作，然后对fil_system->mutex解锁；
[*]对fil_system->mutex加锁，检测space->n_pending_ops，对fil_system->mutex解锁。如果检测到大于0，意味着还有依赖的操作未完成，睡眠20ms后重试；
[*]对fil_system->mutex加锁，检测space->n_pending_flushes和(*node)->n_pending ，对fil_system->mutex解锁。如果检测到大于0，意味着还有依赖的I/O未完成，睡眠20ms后重试；
[*]此时认为已经没有冲突的操作了，刷出所有脏页面或删除所有给定的表空间的页面；
[*]从表空间缓存删除指定space的记录；
[*]删除对应数据文件。
问题结论情况很明确了，主线程获取ibuf的（space，page）的过程与删除操作执行的过程并没有锁保证互斥，只有async I/O完成之后的merge操作与删除操作才有互斥。如果后台线程开始ibuf merge并已经执行过了第2步的检测，但还没有执行到第3步检测，此时用户线程开始做删除表的操作，并设置好stop_new_ops标记但还没有执行到第5步删除表空间缓存，就会出现这个错误信息。两线程的交互如下图所示：
不出意外的话，在打中断点时必然有线程在执行对应表的删除操作。果然我们可以发现如下堆栈：Thread 118 (Thread 0x7f9de0111700 (LWP 5234)):#00x00007fa003ef1e8e in pthread_cond_broadcast@@GLIBC_2.3.2 () from /lib64/libpthread.so.0#10x0000000000f82f41 in broadcast (this=0xd452ef8) at mysql-5.7.22/storage/innobase/os/os0event.cc:184#2set (this=0xd452ef8) at mysql-5.7.22/storage/innobase/os/os0event.cc:75#3os_event_set (event=0xd452ef8) at mysql-5.7.22/storage/innobase/os/os0event.cc:483#40x00000000010ec8a4 in signal (this=<optimized out>) at mysql-5.7.22/storage/innobase/include/ut0mutex.ic:105#5exit (this=<optimized out>) at mysql-5.7.22/storage/innobase/include/ib0mutex.h:690#6exit (this=<optimized out>) at mysql-5.7.22/storage/innobase/include/ib0mutex.h:961#7buf_flush_yield (bpage=<optimized out>, buf_pool=<optimized out>) at mysql-5.7.22/storage/innobase/buf/buf0lru.cc:405#8buf_flush_try_yield (processed=<optimized out>, bpage=<optimized out>, buf_pool=<optimized out>) at mysql-5.7.22/storage/innobase/buf/buf0lru.cc:449#9buf_flush_or_remove_pages (trx=<optimized out>, flush=<optimized out>, observer=<optimized out>, id=<optimized out>, buf_pool=<optimized out>) at mysql-5.7.22/storage/innobase/buf/buf0lru.cc:632#10 buf_flush_dirty_pages (buf_pool=<optimized out>, id=<optimized out>, observer=<optimized out>, flush=<optimized out>, trx=<optimized out>) at mysql-5.7.22/storage/innobase/buf/buf0lru.cc:693#11 0x00000000010f6de7 in buf_LRU_remove_pages (trx=0x0, buf_remove=BUF_REMOVE_FLUSH_NO_WRITE, id=55, buf_pool=0x31e55e8) at mysql-5.7.22/storage/innobase/buf/buf0lru.cc:893#12 buf_LRU_flush_or_remove_pages (id=id@entry=55, buf_remove=buf_remove@entry=BUF_REMOVE_FLUSH_NO_WRITE, trx=trx@entry=0x0) at mysql-5.7.22/storage/innobase/buf/buf0lru.cc:951#13 0x000000000114e488 in fil_delete_tablespace (id=id@entry=55, buf_remove=buf_remove@entry=BUF_REMOVE_FLUSH_NO_WRITE) at mysql-5.7.22/storage/innobase/fil/fil0fil.cc:2800#14 0x0000000000fe77bd in row_drop_single_table_tablespace (trx=0x0, is_encrypted=false, is_temp=false, filepath=0x7f9d7c209f38 "./sbtest/sbtest25.ibd", tablename=0x7f9d7c209dc8 "sbtest/sbtest25", space_id=55) at mysql-5.7.22/storage/innobase/row/row0mysql.cc:4189#15 row_drop_table_for_mysql (name=name@entry=0x7f9de010e020 "sbtest/sbtest25", trx=trx@entry=0x7f9ff9515750, drop_db=<optimized out>, nonatomic=<optimized out>, nonatomic@entry=true, handler=handler@entry=0x0) at mysql-5.7.22/storage/innobase/row/row0mysql.cc:4741#16 0x0000000000f092f3 in ha_innobase::delete_table (this=<optimized out>, name=0x7f9de010f5e0 "./sbtest/sbtest25") at mysql-5.7.22/storage/innobase/handler/ha_innodb.cc:12539#17 0x0000000000801a30 in ha_delete_table (thd=thd@entry=0x7f9d7c1f6910, table_type=table_type@entry=0x2ebd100, path=path@entry=0x7f9de010f5e0 "./sbtest/sbtest25", db=db@entry=0x7f9d7c00e560 "sbtest", alias=0x7f9d7c00df98 "sbtest25", generate_warning=generate_warning@entry=true) at mysql-5.7.22/sql/handler.cc:2586#18 0x0000000000d0a6af in mysql_rm_table_no_locks (thd=thd@entry=0x7f9d7c1f6910, tables=tables@entry=0x7f9d7c00dfe0, if_exists=true, drop_temporary=false, drop_view=drop_view@entry=false, dont_log_query=dont_log_query@entry=false) at mysql-5.7.22/sql/sql_table.cc:2546#19 0x0000000000d0ba58 in mysql_rm_table (thd=thd@entry=0x7f9d7c1f6910, tables=tables@entry=0x7f9d7c00dfe0, if_exists=<optimized out>, drop_temporary=<optimized out>) at mysql-5.7.22/sql/sql_table.cc:2196#20 0x0000000000c9d90b in mysql_execute_command (thd=thd@entry=0x7f9d7c1f6910, first_level=first_level@entry=true) at mysql-5.7.22/sql/sql_parse.cc:3589#21 0x0000000000ca1edd in mysql_parse (thd=thd@entry=0x7f9d7c1f6910, parser_state=parser_state@entry=0x7f9de01107a0) at mysql-5.7.22/sql/sql_parse.cc:5582#22 0x0000000000ca2a20 in dispatch_command (thd=thd@entry=0x7f9d7c1f6910, com_data=com_data@entry=0x7f9de0110e00, command=COM_QUERY) at mysql-5.7.22/sql/sql_parse.cc:1458#23 0x0000000000ca4377 in do_command (thd=thd@entry=0x7f9d7c1f6910) at mysql-5.7.22/sql/sql_parse.cc:999#24 0x0000000000d5ed00 in handle_connection (arg=arg@entry=0x10b8e910) at mysql-5.7.22/sql/conn_handler/connection_handler_per_thread.cc:300#25 0x0000000001223d74 in pfs_spawn_thread (arg=0x10c48f40) at mysql-5.7.22/storage/perfschema/pfs.cc:2190#26 0x00007fa003eeddc5 in start_thread () from /lib64/libpthread.so.0#27 0x00007fa002aab74d in clone () from /lib64/libc.so.6
解决办法为buf_read_ibuf_merge_pages、buf_read_page_low、fil_io新增一个参数ignore_missing_space。表示忽略正在删除的space，默认为false，当ibuf_merge_pages调用的时候置为true。在fil_io报错处额外判断该参数是否为true，是则不报错，继续其他流程。或者直接在buf_read_ibuf_merge_pages调用buf_read_page_low时传入IORequest::IGNORE_MISSING参数。具体代码参考MariaDB commit：8edbb1117a9e1fd81fbd08b8f1d06c72efe38f44影响版本察看相关信息，这个问题是修改Bug#19710564时删除表空间版本引入的。
[*]MySQL Community Server 5.7.6引入，版本5.7.22尚未修复，版本8.0.0已修复。
[*]MariaDB Server 10.2受影响。MariaDB Server 10.2.9, 10.3.2已修复
优化建议可优化一下性能：在buf_read_ibuf_merge_pages中记录下出错的space id，循环的时候判断下一个page的space id，如果space id是相同的，直接删除对应ibuf的记录（当前分配的最大space id记录在系统表空间，space id占4个字节，低于0xFFFFFFF0UL，分配时读取系统表空间保存的值，然后加一，具有唯一性）。
页:
[1]