MySQL在删除表时I/O错误原因分析

最近使用sysbench测试MySQL,由于测试时间较长,写了一个脚本按prepare->run->cleanup的顺序在后台跑着。跑完后察看日志发现一个问题,MySQL服务的错误日志中出现多条类似以下信息的报错:

[ERROR] InnoDB: Trying to do I/O to a tablespace which does not exist. I/O type: read, page: [page id: space=32, page number=57890], 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 #0 fil_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 #1 0x00000000010f99fa 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 #2 0x00000000010fc5fa 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 #3 0x0000000000f3a86c 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 #4 0x0000000000f3a94a in ibuf_merge (sync=false, sync=false, n_pages=0x7f9ddaffce30) at mysql-5.7.22/storage/innobase/ibuf/ibuf0ibuf.cc:2656 #5 ibuf_merge_in_background (full=full@entry=false) at mysql-5.7.22/storage/innobase/ibuf/ibuf0ibuf.cc:2721 #6 0x000000000102bcf4 in srv_master_do_active_tasks () at mysql-5.7.22/storage/innobase/srv/srv0srv.cc:2132 #7 srv_master_thread (arg=<optimized out>) at mysql-5.7.22/storage/innobase/srv/srv0srv.cc:2383 #8 0x00007fa003eeddc5 in start_thread () from /lib64/libpthread.so.0 #9 0x00007fa002aab74d 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后重试;

内容版权声明:除非注明,否则皆为本站原创文章。

转载注明出处:https://www.heiqu.com/wpygpw.html